This adds several options for configuring the log format of timestamps
and severity levels, making it more suitable for integration with log
systems like systemd.
--log-format-timestamp="2006-01-02 15:04:05"
Format for timestamp, set to empty to disable timestamps ($STLOGFORMATTIMESTAMP)
--[no-]log-format-level-string
Whether to include level string in log line ($STLOGFORMATLEVELSTRING)
--[no-]log-format-level-syslog
Whether to include level as syslog prefix in log line ($STLOGFORMATLEVELSYSLOG)
So, to get a timestamp suitable for systemd (syslog prefix, no level
string, no timestamp) we can pass `--log-format-timestamp=""
--no-log-format-level-string --log-format-level-syslog` or,
equivalently, set `STLOGFORMATTIMESTAMP="" STLOGFORMATLEVELSTRING=false
STLOGFORMATLEVELSYSLOG=true`.
Signed-off-by: Jakob Borg <jakob@kastelo.net>
This updates our logging framework from legacy freetext strings using
the `log` package to structured log entries using `log/slog`. I have
updated all INFO or higher level entries, but not yet DEBUG (😓)... So,
at a high level:
There is a slight change in log levels, effectively adding a new warning
level:
- DEBUG is still debug (ideally not for users but developers, though
this is something we need to work on)
- INFO is still info, though I've added more data here, effectively
making Syncthing more verbose by default (more on this below)
- WARNING is a new log level that is different from the _old_ WARNING
(more below)
- ERROR is what was WARNING before -- problems that must be dealt with,
and also bubbled as a popup in the GUI.
A new feature is that the logging level can be set per package to
something other than just debug or info, and hence I feel that we can
add a bit more things into INFO while moving some (in fact, most)
current INFO level warnings into WARNING. For example, I think it's
justified to get a log of synced files in INFO and sync failures in
WARNING. These are things that have historically been tricky to debug
properly, and having more information by default will be useful to many,
while still making it possible get close to told level of inscrutability
by setting the log level to WARNING. I'd like to get to a stage where
DEBUG is never necessary to just figure out what's going on, as opposed
to trying to narrow down a likely bug.
Code wise:
- Our logging object, generally known as `l` in each package, is now a
new adapter object that provides the old API on top of the newer one.
(This should go away once all old log entries are migrated.) This is
only for `l.Debugln` and `l.Debugf`.
- There is a new level tracker that keeps the log level for each
package.
- There is a nested setup of handlers, since the structure mandated by
`log/slog` is slightly convoluted (imho). We do this because we need to
do formatting at a "medium" level internally so we can buffer log lines
in text format but with separate timestamp and log level for the API/GUI
to consume.
- The `debug` API call becomes a `loglevels` API call, which can set the
log level to `DEBUG`, `INFO`, `WARNING` or `ERROR` per package. The GUI
is updated to handle this.
- Our custom `sync` package provided some debugging of mutexes quite
strongly integrated into the old logging framework, only turned on when
`STTRACE` was set to certain values at startup, etc. It's been a long
time since this has been useful; I removed it.
- The `STTRACE` env var remains and can be used the same way as before,
while additionally permitting specific log levels to be specified,
`STTRACE=model:WARN,scanner:DEBUG`.
- There is a new command line option `--log-level=INFO` to set the
default log level.
- The command line options `--log-flags` and `--verbose` go away, but
are currently retained as hidden & ignored options since we set them by
default in some of our startup examples and Syncthing would otherwise
fail to start.
Sample format messages:
```
2009-02-13 23:31:30 INF A basic info line (attr1="val with spaces" attr2=2 attr3="val\"quote" a=a log.pkg=slogutil)
2009-02-13 23:31:30 INF An info line with grouped values (attr1=val1 foo.attr2=2 foo.bar.attr3=3 a=a log.pkg=slogutil)
2009-02-13 23:31:30 INF An info line with grouped values via logger (foo.attr1=val1 foo.attr2=2 a=a log.pkg=slogutil)
2009-02-13 23:31:30 INF An info line with nested grouped values via logger (bar.foo.attr1=val1 bar.foo.attr2=2 a=a log.pkg=slogutil)
2009-02-13 23:31:30 WRN A warning entry (a=a log.pkg=slogutil)
2009-02-13 23:31:30 ERR An error (a=a log.pkg=slogutil)
```
---------
Co-authored-by: Ross Smith II <ross@smithii.com>
Add a commented entry to the systemd service file templates to point
the user in the right direction when using syncOwnership and starting
via systemd. Which is more upgrade-friendly than setting caps on the
executable directly, as mentioned in the docs.
The ```syncthing-resume.service``` will show as a failed service in case
there are no syncthing processes running after resume but it can be
safely ignored because it makes no difference.
GitHub-Pull-Request: https://github.com/syncthing/syncthing/pull/3630
Before this change, issuing either
systemctl --user help syncthing[.service]
or
systemctl help syncthing@user[.service]
gave the message
Can't show: http://docs.syncthing.net/
Following this change the syncthing man page is displayed
This systemd service restarts Syncthing after resume from suspend
via sending SIGHUP. By default Syncthing detects resume from sleep
on its own by looking for jumps in the system clock. Since systemd
knows exactly when the system resumes from sleep let's trigger
the Syncthing restart from there. Doing this in systemd eliminates
some annoying delay, as the service is restarted immediately after
resume. Also, using the systemd dependency mechanism syncthing-inotify
is restarted as well.
$ journalctl -e --identifier syncthing --identifier syncthing-inotify --identifier systemd
Feb 22 09:44:27 kronos systemd[1]: Reached target Sleep.
Feb 22 09:44:27 kronos systemd[1]: Starting Suspend...
Feb 22 09:44:33 kronos systemd[1]: Time has been changed
Feb 22 09:44:33 kronos systemd[963]: Time has been changed
Feb 22 09:44:33 kronos systemd[1]: Started Suspend.
Feb 22 09:44:33 kronos systemd[1]: sleep.target: Unit not needed anymore. Stopping.
Feb 22 09:44:33 kronos systemd[1]: Stopped target Sleep.
Feb 22 09:44:33 kronos systemd[1]: Reached target Suspend.
Feb 22 09:44:33 kronos systemd[1]: suspend.target: Unit is bound to inactive unit systemd-suspend.service. Stopping, too.
Feb 22 09:44:33 kronos systemd[1]: Stopped target Suspend.
Feb 22 09:44:33 kronos systemd[1]: Starting Restart Syncthing after resume...
Feb 22 09:44:33 kronos syncthing[2561]: [35K66] OK: Exiting
Feb 22 09:44:33 kronos systemd[1]: Started Restart Syncthing after resume.
Feb 22 09:44:34 kronos systemd[963]: syncthing.service: Service hold-off time over, scheduling restart.
Feb 22 09:44:34 kronos systemd[963]: Stopping Syncthing Inotify File Watcher...
Feb 22 09:44:34 kronos systemd[963]: Stopped Syncthing Inotify File Watcher.
Feb 22 09:44:34 kronos systemd[963]: Stopped Syncthing - Open Source Continuous File Synchronization.
Feb 22 09:44:34 kronos systemd[963]: Started Syncthing - Open Source Continuous File Synchronization.
Feb 22 09:44:34 kronos systemd[963]: Started Syncthing Inotify File Watcher.
Feb 22 09:44:34 kronos syncthing[2836]: [35K66] INFO: syncthing v0.12.19 "Beryllium Bedbug" (go1.5.3 linux-amd64) builduser@svetlemodry 2016-02-14 19:26:33 UTC
This system service has to be located in "/etc/systemd/system/syncthing-resume.service",
and for packages in "/usr/lib/systemd/system/syncthing-resume.service". It can be
enabled using "systemctl enable syncthing-resume.service".
PR #2578 enables us to remove the exit code 2 from the list of
success status codes, because SIGINT will be handled properly.
I have also converted STNORESTART to --no-restart for the sake
of consistency.
The systemd exit code definitions (introduced in c586a17, refs #1324) caused
problems. Per default systemd considers a return code != 0 as failed. So when
you click on "Restart" in the WebUI an error appears:
systemd[953]: syncthing.service: main process exited, code=exited, status=3/NOTIMPLEMENTED
systemd[953]: Unit syncthing.service entered failed state.
systemd[953]: syncthing.service failed.
systemd[953]: syncthing.service holdoff time over, scheduling restart.
systemd[953]: Started Syncthing - Open Source Continuous File Synchronization.
systemd[953]: Starting Syncthing - Open Source Continuous File Synchronization...
syncthing[13222]: [LFKUK] INFO: syncthing v0.10.30 (go1.4.2 linux-amd64 default) builduser@jara 2015-03-29 07:46:44 UTC
To fix this error we have to add the "succes codes" 2, 3, 4 to
"SuccessExitStatus":
syncthing[13006]: [LFKUK] INFO: Restarting
syncthing[13006]: [LFKUK] OK: Exiting
systemd[953]: syncthing.service holdoff time over, scheduling restart.
systemd[953]: Started Syncthing - Open Source Continuous File Synchronization.
systemd[953]: Starting Syncthing - Open Source Continuous File Synchronization...
syncthing[13031]: [LFKUK] INFO: syncthing v0.10.30 (go1.4.2 linux-amd64 default) builduser@jara 2015-03-29 07:46:44 UTC
To make sure that syncthing restarts in case of error, and to make sure
that "Restart=on-failure" actually works, let's remove
"RestartPreventExitStatus=1". Systemd considers this as an error per
default and the restart will be triggered successfully.
Syncthing should not try to start a browser when invoked by systemd.
Furthermore we do not need any timestamps in the journal as systemd
already handles this for us.
- Removed environment file to keep the service file minimal.
"systemctl edit syncthing.service" does the job if somebody wants
to customize the service.
- Changed "cmdline.target" to "default.target" as "cmdline.target"
does not exist in systemd.special:
http://www.freedesktop.org/software/systemd/man/systemd.special.html
- Added a missing "After=network.target".
- Added a documentation hint, thx @jaystrictor
