Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logfile rotation #2251

Closed
akohlsmith opened this issue Sep 8, 2015 · 21 comments
Closed

logfile rotation #2251

akohlsmith opened this issue Sep 8, 2015 · 21 comments
Labels
enhancement New features or improvements of some kind, as opposed to a problem (bug) frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion

Comments

@akohlsmith
Copy link

Does the -logfile option deal well with the file changing out from underneath syncthing?

@AudriusButkevicius
Copy link
Member

No, and we were reluctant of adding the option due to requests like these.
Your syslogger should deal with rotation, and ideally you should log to stdout and let the service manager deal with it.

@akohlsmith
Copy link
Author

I did not ask if syncthing could do log rotation.

I asked if syncthing's -logfile option correctly deals with logfile rotation. i.e. if an external process does the equivalent of "mv logfile logfile.old" will syncthing correctly recreate the logfile or will it error out? Or what if the logfile is truncated, does syncthing correctly append to the current file position or does it blindly assume that its cached file offset is correct?

syslog subsystems are great in theory. I can appreciate your frustration at some of these feature requests, but logging seems to be something that "stderr piped to syslog" seems only minimally equipped to handle. stderr is typically for errors, not general state logging.

I don't want to tell you how to write your own software, but it seems pretty straightforward to write a logging subsystem that handles the logfile moving without resorting to signals and other cruft. Simply throwing out a logging capability for a process that is designed to run for long periods of time seems ... weak.

@AudriusButkevicius
Copy link
Member

Right, it's a different matter then. I haven't read the initial post properly.

@calmh
Copy link
Member

calmh commented Sep 8, 2015

if an external process does the equivalent of "mv logfile logfile.old" will syncthing correctly recreate the logfile or will it error out

Neither, it'll continue writing to the fd it opened, like any other process. (Except maybe on Windows, where I have no idea what happens...)

What's the proposed thing here?

@akohlsmith
Copy link
Author

The proposed thing would be to have every log "write" be a "open+create+append, write, close" operation so that if the logfile moves, is truncated or otherwise changed syncthing would correctly deal with it. Most logfile rotators just move the file out of the way, but they have options to send signals or other crap that is probably less elegant to deal with than simply always opening the logfile for append, optionally creating it if it doesn't exist, writing what's needed, and closing the file afterward.

There are slicker ways to do this but we're not writing a ton of data nor are we writing it quickly, so the "brute force" method mentioned above is simple, fast and os-agnostic.

@AudriusButkevicius
Copy link
Member

I think we use the stdlib log package, wonder how that deals with this.

@calmh
Copy link
Member

calmh commented Sep 8, 2015

No, in this case we just open a file and write to it, so we could do that.

@calmh calmh added enhancement New features or improvements of some kind, as opposed to a problem (bug) help-wanted labels Sep 8, 2015
@calmh
Copy link
Member

calmh commented Sep 8, 2015

Technically, we need a new io.Writer type that does open+write+close on each write, but that's doable.

(A log line is already a single write each)

@jpjp
Copy link
Contributor

jpjp commented Sep 9, 2015

No no no! If you are not sending a signal to the process after you have rotated its log, you have done your log rotation wrong. If syncthing doesn't support that, then that's an RFE, but asking syncthing to do weird log writing because you forget to send a signal is madness.

@3rdChimp
Copy link

Hi

I'm new in Github so sorry if I break your netiquette
I subscribed to share my experience with logs. I use v0.11.25, Windows (64 bit). Thanks for the software... It's a great product and a big help.

The logfile sudunly become obese. Up to 45 GB. I could not delete the file (or rotate, or truncate) because syncthing has a lock on it, so I had to stop syncthing, delete the log, and start again.

Is there a simple way to limit the quantity of logging produced by syncthing?

Then the problem came back. I decided that I could do without log for a while, and I check the logflag. But there is no "nolog" option. I tried to set the the logfile to "" or /dev/null but it did not work. So I used the logfile=-, and it did not work also : it still created a logfile (I should mention I also use the "no console" option) I tried to put the logfile read-only, but then syncthing would not start. Then I removed the no-console option, and put logfile=- but it stills create a log.

So maybe there is a bug here. I launch it with wsh.Run and intWindowStyle=0, so maybe it is the lack of STDOUt that makes syncthing force log writing on default file even when I specify "-".

So here are a few suggestions:

  • from the web-gui: a command "clear the log"
  • option "no-log"
  • log rotation, or purge... Anything that would keep the logging volume contained

@AudriusButkevicius
Copy link
Member

-logfile=- should work

@3rdChimp
Copy link

Hi

Thank-you for your reply. I went back to my launch process (wsh.Run) and the problem was on my side. Now: I put logfile=- and it does not create a log.

Still, no-logging is only a workaround. I would prefer to have a log that does not reach cyclopean volume. Am I the only one to report this issue?

@calmh
Copy link
Member

calmh commented Sep 20, 2015

So far, yes. What's in the log?

@3rdChimp
Copy link

(I am using cygwin)

$head syncthing.log
[AJZKU] 23:28:43 INFO: syncthing v0.11.25 "Aluminium Ant" (go1.4.2 windows-amd64 default) unknown-user@syncthing-builder 2015-09-13 09:46:17 UTC
[AJZKU] 23:28:43 INFO: My ID: XXX
[AJZKU] 23:28:43 INFO: Database block cache capacity 64626 KiB
[AJZKU] 23:28:44 OK: Ready to synchronize XXX (read-write)
[AJZKU] 23:28:45 OK: Ready to synchronize XXX (read-write)
[AJZKU] 23:28:45 OK: Ready to synchronize XXX (read-write)
[AJZKU] 23:28:45 OK: Ready to synchronize XXX (read-write)
[AJZKU] 23:28:45 INFO: Starting web GUI on https://0.0.0.0:xxxx/
[AJZKU] 23:28:45 INFO: Completed initial scan (rw) of folder XXX
[AJZKU] 23:28:45 INFO: Completed initial scan (rw) of folder XXX

[...]

[AJZKU] 19:00:20 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller (folder "partage_ABC", file "foo\bar\various file"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller (folder "partage_ABC", file "foo\bar\various file"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller (folder "partage_ABC", file "foo\bar\various file"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller (folder "partage_ABC", file "foo\bar\various file"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:00:20 INFO: Folder "partage_ABC" isn't making progress. Pausing puller for 1m0s.

$ls -l syncthing.log
-rwx------+ 1 bmarcel mkgroup 48249307051 Sep 19 19:04 syncthing.log

$ls -lh syncthing.log
-rwx------+ 1 bmarcel mkgroup 45G Sep 19 19:04 syncthing.log

$tail syncthing.log

[AJZKU] 19:04:10 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les53-12-04-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:04:10 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:04:10 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les54-01-27-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:04:10 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:04:10 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les54-06-10-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:04:10 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:04:10 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les54-12-07-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:04:10 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.

$tail syncthing.log
[AJZKU] 19:05:36 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les58-05-05-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les58-10-10-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les58-05-11-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les50-08-11-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller (folder "partage_ABC", file "foo\bar\various file\les54-02-18-p1-bg.jpg"): dst stat dir: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...zmftn: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.
[AJZKU] 19:05:36 INFO: Puller: final: GetFileAttributesEx ?\d:\data\syncthing\partage-XXX...: Le chemin d’accès spécifié est introuvable.

I edited to remove the path and other personal info
Messages are in French. Do you need translation?

This is all that I have, I deleted the rest.

@calmh
Copy link
Member

calmh commented Sep 20, 2015

Looks like it can't find a directory it expects. That's weird. You might solve this by creating it. There's a different bug somewhere in the tracker that triggers this by deleting a directory as it's being scanned/synced, that could be what's happened.

@3rdChimp
Copy link

Yes, probably I was reorganizing my directories on both ends when it happened.
If I remember properly my repair actions, the inflation continued even after I restarted. So I deleted the database and then the inflation stopped.

@MilkWasABadChoice
Copy link

It looks like (at least for now) the expectation is that users will figure out logfile rotation themselves. That's fine – features aren't free – but I'm using the default installation on OS X (via homebrew) and just noticed this:

-rw-r--r-- 1 rickb admin 5320509386 Oct 25 17:39 /usr/local/var/log/syncthing.log

I know, a 5GB log begs the "why?" question, and I'm solving that separately. But if the app can log this much info, I'd like to put something in place to avoid unchecked growth going forward. Is there a standard recommendation for OS X users on how to get logfile rotation for syncthing? The included launchctl plist file just redirects output to that file – AFAICT there's no easy way to pipe through an intermediate process from within a launchctl plist specification.

Barring anything clever, I suspect I'll just add a crontab command to launchctl unload -> rotate -> launchctl load, but I'd rather steal a clever solution than hack together a crappy one.

@calmh
Copy link
Member

calmh commented Oct 29, 2015

Launchd sure seems a bit lacking in that department, yeah.

@calmh calmh closed this as completed in b2855f0 Oct 29, 2015
AudriusButkevicius added a commit that referenced this issue Oct 29, 2015
Enable log rotation by automatically closing log file (fixes #2251)
@claudiodsf
Copy link

@calmh Is this a solution for the current behavior under OS X/homebrew, where stdout and stderr are piped to /usr/local/var/log/syncthing.log ? This file still seems to keep growing (syncthing 0.12.13).

The plist file is at the end of the formula here: https://github.com/Homebrew/homebrew/blob/master/Library/Formula/syncthing.rb

@calmh
Copy link
Member

calmh commented Jan 14, 2016

No, this is unrelated. Something needs to rotate those log files to stop them from growing forever. Possibly launchd already understands what to do when that happens, but someone needs to do it.

@claudiodsf
Copy link

Ok, thanks. So this has to be reported to homebrew, if I well understand.

@st-review st-review added the frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion label Jun 16, 2017
@syncthing syncthing locked and limited conversation to collaborators Jun 16, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
enhancement New features or improvements of some kind, as opposed to a problem (bug) frozen-due-to-age Issues closed and untouched for a long time, together with being locked for discussion
Projects
None yet
Development

No branches or pull requests

8 participants