[pve-devel] [PATCH pve-esxi-import-tools/storage] improve error handling/logging

[pve-devel] [PATCH pve-esxi-import-tools/storage] improve error handling/logging

[Dominik Csapak]

two smaller patches that improve which error gets shown to the user and
logged to syslog in case of an early error when trying to fuse mount

pve-esxi-import-tools:

Dominik Csapak (1):
  improve error handling before mounting

 src/main.rs | 36 +++++++++++++++++++++++++++---------
 1 file changed, 27 insertions(+), 9 deletions(-)

pve-storage:

Dominik Csapak (1):
  esxi: improve error handling for fuse mount tool

 src/PVE/Storage/ESXiPlugin.pm | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

-- 
2.39.2



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

[pve-devel] [PATCH pve-esxi-import-tools 1/1] improve error handling before mounting

[Dominik Csapak]

when we fail early in the mount process, we did not log any error to the
syslog, but only the top most one to stderr.

sadly we were not able to see them anywhere, so improve the log by
* log the complete error chain with log::error (so we also can see the
  causes)
* add more context hints in main_do

This can help debug issues where we failed early and could not see any
error output otherwise, e.g. this thread in the forum:

https://forum.proxmox.com/threads/146248/

Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
---
 src/main.rs | 36 +++++++++++++++++++++++++++---------
 1 file changed, 27 insertions(+), 9 deletions(-)

diff --git a/src/main.rs b/src/main.rs
index 281ec3d..a8b2bb6 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -1,4 +1,5 @@
 use std::ffi::{CString, OsStr, OsString};
+use std::fmt::Write;
 use std::io;
 use std::os::fd::RawFd;
 use std::os::unix::ffi::OsStrExt;
@@ -221,7 +222,12 @@ fn main() {
     });
 
     if let Err(err) = runtime.block_on(main_do()) {
-        eprintln!("Error: {}", err);
+        let mut err_chain = String::new();
+        for err in err.chain() {
+            let _ = writeln!(err_chain, " {err}");
+        }
+        println!("Error: {err}");
+        log::error!("Error: {err_chain}");
         std::process::exit(-1);
     }
 }
@@ -236,15 +242,15 @@ async fn main_do() -> Result<(), Error> {
             usage(&arg0, std::io::stderr(), 1);
         }
     };
-    parse_manifest(&args.manifest)?;
+    parse_manifest(&args.manifest).context("failed to parse manifest")?;
 
     let change_uid = match args.change_user.as_deref() {
-        Some(user) => Some(get_uid(user)?),
+        Some(user) => Some(get_uid(user).context("failed to get uid")?),
         None => None,
     };
 
     let change_gid = match args.change_group.as_deref() {
-        Some(group) => Some(get_gid(group)?),
+        Some(group) => Some(get_gid(group).context("failed to get gid")?),
         None => None,
     };
 
@@ -255,10 +261,12 @@ async fn main_do() -> Result<(), Error> {
         .enable_readdirplus();
 
     for opt in args.mount_options {
-        fuse = fuse.options_os(&opt)?;
+        fuse = fuse
+            .options_os(&opt)
+            .context("failed to get fuse options")?;
     }
 
-    unmount_if_mounted(&args.mount_path)?;
+    unmount_if_mounted(&args.mount_path).context("failed to unmount")?;
 
     let mut fuse = fuse
         .build()
@@ -302,9 +310,19 @@ async fn main_do() -> Result<(), Error> {
             let fs_datastore = fs_datacenter.create_datastore(datastore);
 
             log::debug!("loading {datacenter:?}/{datastore:?}/{path:?}");
-            let config =
-                vmx::VmConfig::parse(client.open_file(datacenter, datastore, path).await?, path)
-                    .await?;
+            let config = vmx::VmConfig::parse(
+                client
+                    .open_file(datacenter, datastore, path)
+                    .await
+                    .with_context(|| {
+                        format!("error opening file for: {datacenter} {datastore} {path}")
+                    })?,
+                path,
+            )
+            .await
+            .with_context(|| {
+                format!("failed to parse vm config for {datacenter} {datastore} {path}")
+            })?;
             log::debug!("{config:#?}");
             for disk in config.disks.values() {
                 let other_fs_datastore;
-- 
2.39.2



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

Re: [pve-devel] [PATCH pve-esxi-import-tools 1/1] improve error handling before mounting

[Thomas Lamprecht]

On 08/05/2024 14:41, Dominik Csapak wrote:
> when we fail early in the mount process, we did not log any error to the
> syslog, but only the top most one to stderr.
> 
> sadly we were not able to see them anywhere, so improve the log by
> * log the complete error chain with log::error (so we also can see the
>   causes)
> * add more context hints in main_do
> 
> This can help debug issues where we failed early and could not see any
> error output otherwise, e.g. this thread in the forum:
> 
> https://forum.proxmox.com/threads/146248/
> 
> Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
> ---
>  src/main.rs | 36 +++++++++++++++++++++++++++---------
>  1 file changed, 27 insertions(+), 9 deletions(-)
> 
> diff --git a/src/main.rs b/src/main.rs
> index 281ec3d..a8b2bb6 100644
> --- a/src/main.rs
> +++ b/src/main.rs
> @@ -1,4 +1,5 @@
>  use std::ffi::{CString, OsStr, OsString};
> +use std::fmt::Write;
>  use std::io;
>  use std::os::fd::RawFd;
>  use std::os::unix::ffi::OsStrExt;
> @@ -221,7 +222,12 @@ fn main() {
>      });
>  
>      if let Err(err) = runtime.block_on(main_do()) {
> -        eprintln!("Error: {}", err);
> +        let mut err_chain = String::new();
> +        for err in err.chain() {
> +            let _ = writeln!(err_chain, " {err}");

is the extra whitespace intended? At least the first line would then have two
consecutive whitespaces, one from here and one from the prefix below on log and
println.

> +        }
> +        println!("Error: {err}");
> +        log::error!("Error: {err_chain}");
>          std::process::exit(-1);
>      }
>  }
> @@ -236,15 +242,15 @@ async fn main_do() -> Result<(), Error> {
>              usage(&arg0, std::io::stderr(), 1);
>          }
>      };
> -    parse_manifest(&args.manifest)?;
> +    parse_manifest(&args.manifest).context("failed to parse manifest")?;
>  
>      let change_uid = match args.change_user.as_deref() {
> -        Some(user) => Some(get_uid(user)?),
> +        Some(user) => Some(get_uid(user).context("failed to get uid")?),
>          None => None,
>      };
>  
>      let change_gid = match args.change_group.as_deref() {
> -        Some(group) => Some(get_gid(group)?),
> +        Some(group) => Some(get_gid(group).context("failed to get gid")?),
>          None => None,
>      };
>  
> @@ -255,10 +261,12 @@ async fn main_do() -> Result<(), Error> {
>          .enable_readdirplus();
>  
>      for opt in args.mount_options {
> -        fuse = fuse.options_os(&opt)?;
> +        fuse = fuse
> +            .options_os(&opt)
> +            .context("failed to get fuse options")?;
>      }
>  
> -    unmount_if_mounted(&args.mount_path)?;
> +    unmount_if_mounted(&args.mount_path).context("failed to unmount")?;
>  
>      let mut fuse = fuse
>          .build()
> @@ -302,9 +310,19 @@ async fn main_do() -> Result<(), Error> {
>              let fs_datastore = fs_datacenter.create_datastore(datastore);
>  
>              log::debug!("loading {datacenter:?}/{datastore:?}/{path:?}");
> -            let config =
> -                vmx::VmConfig::parse(client.open_file(datacenter, datastore, path).await?, path)
> -                    .await?;
> +            let config = vmx::VmConfig::parse(
> +                client
> +                    .open_file(datacenter, datastore, path)
> +                    .await
> +                    .with_context(|| {
> +                        format!("error opening file for: {datacenter} {datastore} {path}")

should that context be added unconditionally in open_file?

Also drop the `for: `, rather something like "error when opening file '{...}'"

And FWIW, in above debug log the variable triple is printed as path,
and it's also accessible that way on FS level, so might make sense to
keep it that way.

> +                    })?,

can we move this to a separate `let config =` line before calling parse on is,
this gets rather convoluted and with rust one can nicely override the same
variable in an explicit way, so this here IMO better expressed that way.

> +                path,
> +            )
> +            .await
> +            .with_context(|| {
> +                format!("failed to parse vm config for {datacenter} {datastore} {path}")
> +            })?;

Similar here, isn't adding that context belonging in the parse fn itself? Might
hold true for the static context too, as long as the context does not include
call-site specific info, but only fn implementation-site one, they might be better
added at the site of implementation to avoid potential repetition.

also s/vm/VM/

>              log::debug!("{config:#?}");
>              for disk in config.disks.values() {
>                  let other_fs_datastore;



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

Re: [pve-devel] [PATCH pve-esxi-import-tools 1/1] improve error handling before mounting

[Dominik Csapak]

On 5/8/24 16:26, Thomas Lamprecht wrote:
> On 08/05/2024 14:41, Dominik Csapak wrote:
>> when we fail early in the mount process, we did not log any error to the
>> syslog, but only the top most one to stderr.
>>
>> sadly we were not able to see them anywhere, so improve the log by
>> * log the complete error chain with log::error (so we also can see the
>>    causes)
>> * add more context hints in main_do
>>
>> This can help debug issues where we failed early and could not see any
>> error output otherwise, e.g. this thread in the forum:
>>
>> https://forum.proxmox.com/threads/146248/
>>
>> Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
>> ---
>>   src/main.rs | 36 +++++++++++++++++++++++++++---------
>>   1 file changed, 27 insertions(+), 9 deletions(-)
>>
>> diff --git a/src/main.rs b/src/main.rs
>> index 281ec3d..a8b2bb6 100644
>> --- a/src/main.rs
>> +++ b/src/main.rs
>> @@ -1,4 +1,5 @@
>>   use std::ffi::{CString, OsStr, OsString};
>> +use std::fmt::Write;
>>   use std::io;
>>   use std::os::fd::RawFd;
>>   use std::os::unix::ffi::OsStrExt;
>> @@ -221,7 +222,12 @@ fn main() {
>>       });
>>   
>>       if let Err(err) = runtime.block_on(main_do()) {
>> -        eprintln!("Error: {}", err);
>> +        let mut err_chain = String::new();
>> +        for err in err.chain() {
>> +            let _ = writeln!(err_chain, " {err}");
> 
> is the extra whitespace intended? At least the first line would then have two
> consecutive whitespaces, one from here and one from the prefix below on log and
> println.

yes that was intentionally, but the whitespace in log was not
i wanted to print something like:

Error: <error1>
  <error2>
  <error3>
etc.

we could ofc print them all in one line too... but not a big fan of that
for readability

> 
>> +        }
>> +        println!("Error: {err}");
>> +        log::error!("Error: {err_chain}");
>>           std::process::exit(-1);
>>       }
>>   }
>> @@ -236,15 +242,15 @@ async fn main_do() -> Result<(), Error> {
>>               usage(&arg0, std::io::stderr(), 1);
>>           }
>>       };
>> -    parse_manifest(&args.manifest)?;
>> +    parse_manifest(&args.manifest).context("failed to parse manifest")?;
>>   
>>       let change_uid = match args.change_user.as_deref() {
>> -        Some(user) => Some(get_uid(user)?),
>> +        Some(user) => Some(get_uid(user).context("failed to get uid")?),
>>           None => None,
>>       };
>>   
>>       let change_gid = match args.change_group.as_deref() {
>> -        Some(group) => Some(get_gid(group)?),
>> +        Some(group) => Some(get_gid(group).context("failed to get gid")?),
>>           None => None,
>>       };
>>   
>> @@ -255,10 +261,12 @@ async fn main_do() -> Result<(), Error> {
>>           .enable_readdirplus();
>>   
>>       for opt in args.mount_options {
>> -        fuse = fuse.options_os(&opt)?;
>> +        fuse = fuse
>> +            .options_os(&opt)
>> +            .context("failed to get fuse options")?;
>>       }
>>   
>> -    unmount_if_mounted(&args.mount_path)?;
>> +    unmount_if_mounted(&args.mount_path).context("failed to unmount")?;
>>   
>>       let mut fuse = fuse
>>           .build()
>> @@ -302,9 +310,19 @@ async fn main_do() -> Result<(), Error> {
>>               let fs_datastore = fs_datacenter.create_datastore(datastore);
>>   
>>               log::debug!("loading {datacenter:?}/{datastore:?}/{path:?}");
>> -            let config =
>> -                vmx::VmConfig::parse(client.open_file(datacenter, datastore, path).await?, path)
>> -                    .await?;
>> +            let config = vmx::VmConfig::parse(
>> +                client
>> +                    .open_file(datacenter, datastore, path)
>> +                    .await
>> +                    .with_context(|| {
>> +                        format!("error opening file for: {datacenter} {datastore} {path}")
> 
> should that context be added unconditionally in open_file?

how do you mean? there is only one function in open_file that can fail, so do you mean there?

AFAIU with_context/context is only implemented on Result/Option and there is no way to 'add it' to a
function for all `foo()?` calls automatically? (or maybe I'm misunderstanding something here?)

> 
> Also drop the `for: `, rather something like "error when opening file '{...}'"
> 
> And FWIW, in above debug log the variable triple is printed as path,
> and it's also accessible that way on FS level, so might make sense to
> keep it that way.

yep, I'll use the same format

> 
>> +                    })?,
> 
> can we move this to a separate `let config =` line before calling parse on is,
> this gets rather convoluted and with rust one can nicely override the same
> variable in an explicit way, so this here IMO better expressed that way.

sure

> 
>> +                path,
>> +            )
>> +            .await
>> +            .with_context(|| {
>> +                format!("failed to parse vm config for {datacenter} {datastore} {path}")
>> +            })?;
> 
> Similar here, isn't adding that context belonging in the parse fn itself? Might
> hold true for the static context too, as long as the context does not include
> call-site specific info, but only fn implementation-site one, they might be better
> added at the site of implementation to avoid potential repetition.

here we don't have that path in parse anymore (only the underlying fs path that we probably
don't want to log here)

> 
> also s/vm/VM/
> 
>>               log::debug!("{config:#?}");
>>               for disk in config.disks.values() {
>>                   let other_fs_datastore;
> 



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

[pve-devel] [PATCH storage 1/1] esxi: improve error handling for fuse mount tool

[Dominik Csapak]

if the fuse tool encounters an error early, it prints it like:
   Error: some error message
on stderr.

We can capture that here by redirecting STDERR to $wr and die'ing with
the error message.

With this we die with the original error message instead of only
with the return code which is telling the user nothing and does not
help us debug.

Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
---
 src/PVE/Storage/ESXiPlugin.pm | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/src/PVE/Storage/ESXiPlugin.pm b/src/PVE/Storage/ESXiPlugin.pm
index b8bce0e..8dc33fc 100644
--- a/src/PVE/Storage/ESXiPlugin.pm
+++ b/src/PVE/Storage/ESXiPlugin.pm
@@ -222,6 +222,10 @@ sub esxi_mount : prototype($$$;$) {
 		// die "failed to get file descriptor flags: $!\n";
 	    fcntl($wr, F_SETFD, $flags & ~FD_CLOEXEC)
 		// die "failed to remove CLOEXEC flag from fd: $!\n";
+
+	    # capture errors from stderr
+	    open(STDERR, ">&", \*$wr) or die "unable to redirect STDERR: $!\n";
+
 	    # FIXME: use the user/group options!
 	    exec {$ESXI_FUSE_TOOL}
 		$ESXI_FUSE_TOOL,
@@ -245,7 +249,7 @@ sub esxi_mount : prototype($$$;$) {
     undef $wr;
 
     my $result = do { local $/ = undef; <$rd> };
-    if ($result =~ /^ERROR: (.*)$/) {
+    if ($result =~ /^ERROR: (.*)$/i) {
 	die "$1\n";
     }
 
-- 
2.39.2



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

Re: [pve-devel] [PATCH storage 1/1] esxi: improve error handling for fuse mount tool

[Thomas Lamprecht]

On 08/05/2024 14:41, Dominik Csapak wrote:
> if the fuse tool encounters an error early, it prints it like:
>    Error: some error message
> on stderr.
> 
> We can capture that here by redirecting STDERR to $wr and die'ing with

using just a variable name like $wr without context in a commit message
is hardly telling or useful, maybe replace above and the paragraph below
with something like:

"Redirect the STDERR of the child process that mounts the ESXi instance to
the pipe of the parent (API) process, so that it can pass a hopefully more
meaningful message to the user than just an erroneous return code."


> the error message.
> 
> With this we die with the original error message instead of only
> with the return code which is telling the user nothing and does not
> help us debug.
> 
> Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
> ---
>  src/PVE/Storage/ESXiPlugin.pm | 6 +++++-
>  1 file changed, 5 insertions(+), 1 deletion(-)
> 
> diff --git a/src/PVE/Storage/ESXiPlugin.pm b/src/PVE/Storage/ESXiPlugin.pm
> index b8bce0e..8dc33fc 100644
> --- a/src/PVE/Storage/ESXiPlugin.pm
> +++ b/src/PVE/Storage/ESXiPlugin.pm
> @@ -222,6 +222,10 @@ sub esxi_mount : prototype($$$;$) {
>  		// die "failed to get file descriptor flags: $!\n";
>  	    fcntl($wr, F_SETFD, $flags & ~FD_CLOEXEC)
>  		// die "failed to remove CLOEXEC flag from fd: $!\n";
> +
> +	    # capture errors from stderr

nit: you capture all that gets printed to stderr, not just errors, and no
hard feelings, but the comment feels a tiny bit superfluous, at least with
the error message.

> +	    open(STDERR, ">&", \*$wr) or die "unable to redirect STDERR: $!\n";

Don't the \ reference operator and the * dereference operator here cancel
each other out?

> +
>  	    # FIXME: use the user/group options!
>  	    exec {$ESXI_FUSE_TOOL}
>  		$ESXI_FUSE_TOOL,
> @@ -245,7 +249,7 @@ sub esxi_mount : prototype($$$;$) {
>      undef $wr;
>  
>      my $result = do { local $/ = undef; <$rd> };
> -    if ($result =~ /^ERROR: (.*)$/) {
> +    if ($result =~ /^ERROR: (.*)$/i) {
>  	die "$1\n";
>      }
>  



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel

Re: [pve-devel] [PATCH storage 1/1] esxi: improve error handling for fuse mount tool

[Dominik Csapak]

On 5/8/24 16:43, Thomas Lamprecht wrote:
> On 08/05/2024 14:41, Dominik Csapak wrote:
>> if the fuse tool encounters an error early, it prints it like:
>>     Error: some error message
>> on stderr.
>>
>> We can capture that here by redirecting STDERR to $wr and die'ing with
> 
> using just a variable name like $wr without context in a commit message
> is hardly telling or useful, maybe replace above and the paragraph below
> with something like:
> 
> "Redirect the STDERR of the child process that mounts the ESXi instance to
> the pipe of the parent (API) process, so that it can pass a hopefully more
> meaningful message to the user than just an erroneous return code."
> 
> 

You're right, that sounds better

>> the error message.
>>
>> With this we die with the original error message instead of only
>> with the return code which is telling the user nothing and does not
>> help us debug.
>>
>> Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
>> ---
>>   src/PVE/Storage/ESXiPlugin.pm | 6 +++++-
>>   1 file changed, 5 insertions(+), 1 deletion(-)
>>
>> diff --git a/src/PVE/Storage/ESXiPlugin.pm b/src/PVE/Storage/ESXiPlugin.pm
>> index b8bce0e..8dc33fc 100644
>> --- a/src/PVE/Storage/ESXiPlugin.pm
>> +++ b/src/PVE/Storage/ESXiPlugin.pm
>> @@ -222,6 +222,10 @@ sub esxi_mount : prototype($$$;$) {
>>   		// die "failed to get file descriptor flags: $!\n";
>>   	    fcntl($wr, F_SETFD, $flags & ~FD_CLOEXEC)
>>   		// die "failed to remove CLOEXEC flag from fd: $!\n";
>> +
>> +	    # capture errors from stderr
> 
> nit: you capture all that gets printed to stderr, not just errors, and no
> hard feelings, but the comment feels a tiny bit superfluous, at least with
> the error message.

true, i'll remove the comment

> 
>> +	    open(STDERR, ">&", \*$wr) or die "unable to redirect STDERR: $!\n";
> 
> Don't the \ reference operator and the * dereference operator here cancel
> each other out?

yes, of course, i'll remove those

> 
>> +
>>   	    # FIXME: use the user/group options!
>>   	    exec {$ESXI_FUSE_TOOL}
>>   		$ESXI_FUSE_TOOL,
>> @@ -245,7 +249,7 @@ sub esxi_mount : prototype($$$;$) {
>>       undef $wr;
>>   
>>       my $result = do { local $/ = undef; <$rd> };
>> -    if ($result =~ /^ERROR: (.*)$/) {
>> +    if ($result =~ /^ERROR: (.*)$/i) {
>>   	die "$1\n";
>>       }
>>   
> 



_______________________________________________
pve-devel mailing list
pve-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel