 |
I could not reproduce this problem. In my test environment, Director and storage daemon both run virtually and the filedaemon runs on a OS X system. Time was set 30 seconds off, yet the estimation did not return any errors. |
|
|
A quick look at the code indicates, that this warning is only produced if level=since, not level=incremental. Are you sure it happens on your system with level=incremental? |
|
|
@joergs: level can be incremental or full. I've not tried other variations. |
|
|
I checked against 16.2.7 and now also verified that the code has not changed between 16.2.4 and 16.2.7. Setting the filed to debug level 10 (very much output!) will contain the line "level_cmd: ...". It must be since_utime in your case, maybe because of accurate. Debug level can be changed during runtime using setdebug client=<NAME> level=10 trace=1 Result will be written to a trace file. |
|
|
@joergs: I just set one of the clients to a time about 10 mins earlier than the director's (and storage's, since they are on the same system). I re-ran my experiment, just as before, and I get the same result as I reported originally. I tried the setdebug as you described. The audit log indicates that the command was received; no error there. So I am assuming that debugging is set, yet the main bareos log does not show any new messages other than the usual ones. The client I tested against is running bareos-fd 14.2.1, which is a bit older, and may explain why you don't see the same problem. And also maybe why the debugging doesn't kick in. I have upgraded the client as much as I can using the repos, short of building the client myself. I'll see if anti-X might have newer package updates for the client. The other clients are also at various levels of the client (filedaemon). |
|
|
Would running bareos in compatibility mode help to eliminate these messages, or would that just introduce more problems? |
|
|
Debug is not written to the main bareos.log file, but to a local trace file. Issuing the setdebug command tells you where to find this file. Compatibility mode should have no impact on this. So the error did only occur with old bareos filedaemons? Sorry, but the version should be at least 16.2, better 7.2 or master (experimental, nightly) to be relevant for us. What platform are the clients running on? |
|
|
@joergs: "Local?" to what? Local to the system where the setdebug was run, or local to where the filedaemon is running? Or local to where the director is running? I just ran setdebug again, and it did not indicate where the output was going. Could not parse: at least 16.2, better 7.2 -- what does this mean? Anti-X repo version is 14.2.1. There is no update available. However, keep in mind that other clients have seen this error, and they are running other versions of the file daemon software (depending on the distro). There's a couple of debian variants, and an arch-based system. |
|
|
Local: local on the system that runs the daemon. In case of "setdebug client=>NAME>" it is on the client. at least 16.2, better 7.2 => at least 16.2, better 17.2 |
|
|
OK, so I have setdebug as requested, found the trace file (it was not obvious to me where "current directory" might be), and yes, found since_utime= entries in the output. But I assure you I am running these backups ONLY as full or incremental. I do not use any others (even differential). Here is an extract from the trace file: $ grep level_cmd /shared/antix-fd.trace antix-fd: dir_cmd.c:1228-0 level_cmd: level = accurate_incremental mtime_only=0 antix-fd: dir_cmd.c:1228-0 level_cmd: level = since_utime 1524830415 mtime_only=0 prev_job=antix-sys.2018-04-27_05.00.00_10 antix-fd: dir_cmd.c:1228-0 level_cmd: level = accurate_incremental mtime_only=0 antix-fd: dir_cmd.c:1228-0 level_cmd: level = since_utime 1524830415 mtime_only=0 prev_job=antix-sys.2018-04-27_05.00.00_10 antix-fd: dir_cmd.c:1228-0 level_cmd: level = incremental mtime_only=0 antix-fd: dir_cmd.c:1228-0 level_cmd: level = since_utime 1524830415 mtime_only=0 prev_job=antix-sys.2018-04-27_05.00.00_10 antix-fd: dir_cmd.c:1228-0 level_cmd: level = accurate_incremental mtime_only=0 antix-fd: dir_cmd.c:1228-0 level_cmd: level = since_utime 1524830438 mtime_only=0 prev_job=antix-user.2018-04-27_05.00.01_11 antix-fd: dir_cmd.c:1228-0 level_cmd: level = incremental mtime_only=0 antix-fd: dir_cmd.c:1228-0 level_cmd: level = since_utime 1524830438 mtime_only=0 prev_job=antix-user.2018-04-27_05.00.01_11 |
|
|
This error has surfaced again, today. I have searched the logs in /var/log/bareos, /var/log/syslog, and my own logging and cannot force an explanation out of any of them. The strangest part of this is that the first of two jobs failed on just two Vbox VM filedaemons, the other of the two ran fine on each of the two systems. These run smoothly every day, nearly forever (I'm not complaining, believe me). It's just that every so often, I see this crop up. I might not see it again for a long time. I note that bareos tools do more audit logging in some tools than others. For instance, the audit log for today is relatively "quiet" for the jobs I run overnight, but the log gets noisy, logging every SQL query when I run BAT. I will see if I can get more "noise" from bconsole. The director (dir 16.2.4) and storage (sd 16.2.4) daemons are still running on Ubuntu 14.04. The clients affected today were Devuan Jessie (fd 14.2.1) and Anti-X (fd 14.2.1). As I mentioned, these backups run without serious* issues over 99% of the time, which makes this an intermittent problem, and thus one that is hard to nail down the source of. Increasing the verbosity of the tools to the logs will be helpful, and I will look into this. (* sometimes clocks are off, but this presents no serious problem; the jobs do not fail in those instances) |
|
|
I have debug logging running on the director (I may add logging for other daemons later if needed). Log level is set to 200. It would be helpful to have a listing of debug levels. I want to be sure to gather enough debugging info to pin down problems when they come up, but not so much that it will eat disk space unnecessarily. Now I wait for the next time there is a problem and see if there is adequate log output to analyze it. |
|
|
I have now enabled debugging on calls to bconsole for one backup which fails as described. This might be helpful, too, since the failure occurs while bconsole is running. |
|
|
I have now enabled debugging on all jobs. |
|
|
I just realized this wasn't the bug I was trying to address with the debug statements (though they will help perhaps). The other problem I have is with backups that fail in bconsole (not just issue warning) when requesting an estimate. At any rate, maybe this additional logging will help going forward for any sort of issue that arises. The logging does not add a significant amount of disk usage at level 200. |
|
|
So I reproduced this again and got the same warning, but with the name of the filedaemon as source of the warning. Identifying the out-of-sync client is doable. The job itself also runs perfectly fine. I get the following output when running a job on a client with time difference > 60s: 04-Jun 13:35 ubuntu1604-VirtualBox-dir JobId 10: Start Backup JobId 10, Job=macbook-log-backup.2018-06-04_13.35.08_12 04-Jun 13:35 ubuntu1604-VirtualBox-dir JobId 10: Created new Volume "Incremental-0002" in catalog. 04-Jun 13:35 ubuntu1604-VirtualBox-dir JobId 10: Using Device "FileStorage" to write. 04-Jun 13:32 macbook-fd JobId 10: DIR and FD clocks differ by -180 seconds, FD automatically compensating. 04-Jun 13:32 macbook-fd JobId 10: Warning: LZ4 compression support requested in fileset but not available on this platform. Disabling ... 04-Jun 13:35 ubuntu1604-VirtualBox-sd JobId 10: Labeled new Volume "Incremental-0002" on device "FileStorage" (/var/lib/bareos/storage). 04-Jun 13:35 ubuntu1604-VirtualBox-sd JobId 10: Wrote label to prelabeled Volume "Incremental-0002" on device "FileStorage" (/var/lib/bareos/storage) 04-Jun 13:35 ubuntu1604-VirtualBox-sd JobId 10: Elapsed time=00:00:01, Transfer rate=19.44 K Bytes/second 04-Jun 13:35 ubuntu1604-VirtualBox-dir JobId 10: sql_create.c:872 Insert of attributes batch table done 04-Jun 13:35 ubuntu1604-VirtualBox-dir JobId 10: Bareos ubuntu1604-VirtualBox-dir 17.2.4 (21Sep17): Build OS: i686-pc-linux-gnu ubuntu Ubuntu 16.04 LTS JobId: 10 Job: macbook-log-backup.2018-06-04_13.35.08_12 Backup Level: Incremental, since=2018-05-17 13:11:57 Client: "macbook-fd" 17.2.4 (21Sep17) x86_64-apple-darwin17.4.0,osx,17.4.0 FileSet: "MacbookLogFileset" 2018-05-17 13:00:50 Pool: "Incremental" (From Job IncPool override) Catalog: "MyCatalog" (From Client resource) Storage: "ubuntu1604-VirtualBox-sd" (From Job resource) Scheduled time: 04-Jun-2018 13:35:06 Start time: 04-Jun-2018 13:35:14 End time: 04-Jun-2018 13:35:14 Elapsed time: 0 secs Priority: 10 FD Files Written: 7 SD Files Written: 7 FD Bytes Written: 18,515 (18.51 KB) SD Bytes Written: 19,448 (19.44 KB) Rate: 0.0 KB/s Software Compression: None VSS: no Encryption: no Accurate: no Volume name(s): Incremental-0002 Volume Session Id: 1 Volume Session Time: 1528110773 Last Volume Bytes: 20,363 (20.36 KB) Non-fatal FD errors: 0 SD Errors: 0 FD termination status: OK SD termination status: OK Termination: Backup OK |
|
|
The more vexing problem is the other one. Many times, a call to bconsole for an estimate of backup size fails. I am now able to compare debug traces of normal (non-failing) job and failing job (debug level is 200). So far, my investigation reveals "bconsole (100): console.c:346-0 Got poll BNET_EOD" appears in the trace only once for a normal job, but twice for the failing job. This "once versus twice" behavior seems to be consistent in comparing failed to normal jobs. I note it is possible the 2nd message, if it is indeed actually sent by the director, might be getting swallowed by my logging as the result, perhaps, of my script closing the pipe before some final flush of messages to my script, or something like that. I'll double-check the perl code I wrote, but I have been running this script for years now and has always had this intermittent results from the 'estimate' command. bconsole estimate is called from perl as a "Command Before Job". In both scenarios, bconsole connects successfully with the director. I can see the 'estimate' request in the director's trace in both instances. Is there a much better way to obtain the estimate? If I end up with some run-away job (meaning huge amounts of data have appeared since the last run), I don't want to end up eating gobs of backup disk space (and time!). One example of this is backing up the home directory where, say, a program has experienced extremely increased amounts of data in its files. I have excluded a long list of files and directories in all backups, but every so often another one would come along that I had overlooked that just happened to bollix the works. This call to bconsole for an estimate prior to the run is just an additional prevention. |
|
|
I have (finally) gotten around to upgrading my backups. I am using bareos 18.2.5 on the host, and that comes from the bareos repo, not my distro's (Devuan). The clients are running bareos 16.2.4, 16.2.6, or 17.2.5; these come from the respective distros, but they and the director are all running on Linux. This morning, I was greeted with messages that the file daemons were out of sync on 3 of the clients. Again, I am not certain which ones, because the messages indicate neither the client involved nor even the job id (which is always zero in these messages). I think I'd like to change the title of this issue to something like "phantom error messages due to client clocks out of sync with director" which would be much clearer. I did not know, when I first filed this bug, what the nature of the problem was in the first place. These messages do not represent true errors as such since the system adjusts itself anyway. But the messages are unhelpful as they stand; even if I were to investigate the time disparities, I won't get too far since I can't tell which one of the clients are out of sync. Is it possible to either eliminate these messages altogether (since the situations they represent seem to be self-healing), or to include either the job number or the client name (or both) in these messages? I'd be happy to go around fixing my time problems, but generally I do not witness significant time differences by the time I go to investigate. As far as I know, all my clients are sync'ing to one time server on my network. |
|
|
Is this reproducible with supported OS and recent Bareos 22.1.0 code ? Did you ever tried to use a runscript command (one on the FD, one on the dir to show date/time when job start?) |
|
|
closing no feedback, nor being still a problem with recent code. |
- Anonymous
