[pve-devel] [PATCH manager v2] Fix #482: Add timestamps to backup creation log

[Thomas Lamprecht]

On 4/16/19 11:57 AM, Dominic Jäger wrote:
> Adding timestamps to the log messages facilitates troubleshooting.
> 
> Signed-off-by: Dominic Jäger <d.jaeger at proxmox.com>
> ---
> v1->v2
> Initially, I sticked to the rest of the code.
> E.g. line 778 uses +1900 for the years aswell.
> Now the more concise strftime is used.

Ah, yeah I now see where you got this idea from, I fixed that up to a bit
more readable strfmt so that no one else copies that code again...^^
you need to rebase this, but a 3-way merge should resolve it just fine™.

> 
> 
>  PVE/VZDump.pm | 12 ++++++++++--
>  1 file changed, 10 insertions(+), 2 deletions(-)
> 
> diff --git a/PVE/VZDump.pm b/PVE/VZDump.pm
> index 7fc69f98..14b000bd 100644
> --- a/PVE/VZDump.pm
> +++ b/PVE/VZDump.pm
> @@ -11,6 +11,7 @@ use File::Path;
>  use PVE::RPCEnvironment;
>  use PVE::Storage;
>  use PVE::Cluster qw(cfs_read_file);
> +use POSIX qw(strftime);
>  use Time::localtime;
>  use Time::Local;
>  use PVE::JSONSchema qw(get_standard_option);
> @@ -833,7 +834,10 @@ sub exec_backup_task {
>  
>  	unlink $logfile;
>  
> -	debugmsg ('info',  "Starting Backup of VM $vmid ($vmtype)", $logfd, 1);
> +	debugmsg ('info', "Starting Backup of VM $vmid ($vmtype)", $logfd, 1);
> +	my $start_msg_time = localtime();
> +	debugmsg ('info', "Backup started at "
> +	    .strftime("%Y-%m-%d %H:%M:%S", @$start_msg_time)."\n", $logfd);

the array ref looked also a bit strange, but I saw that we include
Time::localtime, which overwrites perl's localtime() (which would return
an array in such a context, and could be used plainly, as I suggested.
The \n at end is not needed, AFAICT?

I looked a little bit closer now, and also think that passing $logfd is
useless here, it's the on backup target storage $basename.log file
(remember, the one that thanks of you, now gets cleaned up on backup
removal), they include also the date/time on every line, so no need for
it there too.

Also, %F can be used as shortcut for %Y-%m-%d (already used in debugmsg,
where I got it from), so you could shorten this and bring it to a single
line, I think.

So, would you willing to send a v3? I know that could have all be seen
on my v1 review already, so sorry, but I only got to give this a real
close look now :-) Thanks!

>  
>  	$plugin->set_logfd ($logfd);
>  
> @@ -1045,17 +1049,21 @@ sub exec_backup_task {
>  
>      my $delay = $task->{backuptime} = time () - $vmstarttime;
>  
> +    my $end_msg_time = localtime();
>      if ($err) {
>  	$task->{state} = 'err';
>  	$task->{msg} = $err;
>  	debugmsg ('err', "Backup of VM $vmid failed - $err", $logfd, 1);
> -
> +	debugmsg ('info', "Backup failed at "
> +	    .strftime("%Y-%m-%d %H:%M:%S", @$end_msg_time)."\n", $logfd);

extra newline and %F as above

>  	eval { $self->run_hook_script ('backup-abort', $task, $logfd); };
>  
>      } else {
>  	$task->{state} = 'ok';
>  	my $tstr = format_time ($delay);
>  	debugmsg ('info', "Finished Backup of VM $vmid ($tstr)", $logfd, 1);
> +	debugmsg ('info', "Backup finished at "
> +	    .strftime("%Y-%m-%d %H:%M:%S", @$end_msg_time)."\n", $logfd);

extra newline and %F as above

>      }
>  
>      close ($logfd) if $logfd;
>