[pbs-devel] [PATCH proxmox-backup] server/worker_task: fix 'unknown' status for some big task logs

[pbs-devel] [PATCH proxmox-backup] server/worker_task: fix 'unknown' status for some big task logs

[Dominik Csapak]

when trying to parse the task status, we seek 8k from the end
which may be into the middle of a line, so the datetime parsing
can fail (when the log message contains ': ')
so try the next line when the first datetime parsing fails

if it was really a broken datetime, we now return either
the datetime of the next line or an 'Unknown' TaskState
(which was the fallback of most call sites anyway)

Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
---
we could save the error for later returning, but
since that does not matter most of the time i did not do that
but if wanted i can send a v2 or fixup for that

 src/server/worker_task.rs | 17 ++++++++++++++---
 1 file changed, 14 insertions(+), 3 deletions(-)

diff --git a/src/server/worker_task.rs b/src/server/worker_task.rs
index a9e4a36a..f6d12ac3 100644
--- a/src/server/worker_task.rs
+++ b/src/server/worker_task.rs
@@ -209,14 +209,25 @@ pub fn upid_read_status(upid: &UPID) -> Result<TaskState, Error> {
 
     let reader = BufReader::new(file);
 
+    let mut first_line = true;
     for line in reader.lines() {
         let line = line?;
 
         let mut iter = line.splitn(2, ": ");
         if let Some(time_str) = iter.next() {
-            endtime = chrono::DateTime::parse_from_rfc3339(time_str)
-                .map_err(|err| format_err!("cannot parse '{}': {}", time_str, err))?
-                .timestamp();
+            let dt_parse_res = chrono::DateTime::parse_from_rfc3339(time_str)
+                .map_err(|err| format_err!("cannot parse timestamp '{}': {}", time_str, err));
+            endtime = if first_line {
+                first_line = false;
+                match dt_parse_res {
+                    Ok(dt) => dt.timestamp(),
+                    // we maybe seeked into the middle of a line,
+                    // so ignore errors on the first
+                    Err(_) => continue,
+                }
+            } else {
+                dt_parse_res?.timestamp()
+            };
         } else {
             continue;
         }
-- 
2.20.1

Re: [pbs-devel] [PATCH proxmox-backup] server/worker_task: fix 'unknown' status for some big task logs

[Dietmar Maurer]

cant we simply skip the first line?

let reader = BufReader::new(file);
let lines = reader.lines();
lines.next()?; // skip first

// Then parse the rest
for line in lines {

}

> On 09/03/2020 11:39 AM Dominik Csapak <d.csapak@proxmox.com> wrote:
> 
>  
> when trying to parse the task status, we seek 8k from the end
> which may be into the middle of a line, so the datetime parsing
> can fail (when the log message contains ': ')
> so try the next line when the first datetime parsing fails
> 
> if it was really a broken datetime, we now return either
> the datetime of the next line or an 'Unknown' TaskState
> (which was the fallback of most call sites anyway)
> 
> Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
> ---
> we could save the error for later returning, but
> since that does not matter most of the time i did not do that
> but if wanted i can send a v2 or fixup for that
> 
>  src/server/worker_task.rs | 17 ++++++++++++++---
>  1 file changed, 14 insertions(+), 3 deletions(-)
> 
> diff --git a/src/server/worker_task.rs b/src/server/worker_task.rs
> index a9e4a36a..f6d12ac3 100644
> --- a/src/server/worker_task.rs
> +++ b/src/server/worker_task.rs
> @@ -209,14 +209,25 @@ pub fn upid_read_status(upid: &UPID) -> Result<TaskState, Error> {
>  
>      let reader = BufReader::new(file);
>  
> +    let mut first_line = true;
>      for line in reader.lines() {
>          let line = line?;
>  
>          let mut iter = line.splitn(2, ": ");
>          if let Some(time_str) = iter.next() {
> -            endtime = chrono::DateTime::parse_from_rfc3339(time_str)
> -                .map_err(|err| format_err!("cannot parse '{}': {}", time_str, err))?
> -                .timestamp();
> +            let dt_parse_res = chrono::DateTime::parse_from_rfc3339(time_str)
> +                .map_err(|err| format_err!("cannot parse timestamp '{}': {}", time_str, err));
> +            endtime = if first_line {
> +                first_line = false;
> +                match dt_parse_res {
> +                    Ok(dt) => dt.timestamp(),
> +                    // we maybe seeked into the middle of a line,
> +                    // so ignore errors on the first
> +                    Err(_) => continue,
> +                }
> +            } else {
> +                dt_parse_res?.timestamp()
> +            };
>          } else {
>              continue;
>          }
> -- 
> 2.20.1
> 
> 
> 
> _______________________________________________
> pbs-devel mailing list
> pbs-devel@lists.proxmox.com
> https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel

Re: [pbs-devel] [PATCH proxmox-backup] server/worker_task: fix 'unknown' status for some big task logs

[Dominik Csapak]

On 9/3/20 12:36 PM, Dietmar Maurer wrote:
> cant we simply skip the first line?
> 
> let reader = BufReader::new(file);
> let lines = reader.lines();
> lines.next()?; // skip first
> 
> // Then parse the rest
> for line in lines {
> 
> }

no for two reasons:

if the task log contains only one line (this happens, e.g. 'TASK OK')
or if the last Log line is exactly 8k long (i am not sure that could happen)

for the first we could check if the file is < 8k long

> 
>> On 09/03/2020 11:39 AM Dominik Csapak <d.csapak@proxmox.com> wrote:
>>
>>   
>> when trying to parse the task status, we seek 8k from the end
>> which may be into the middle of a line, so the datetime parsing
>> can fail (when the log message contains ': ')
>> so try the next line when the first datetime parsing fails
>>
>> if it was really a broken datetime, we now return either
>> the datetime of the next line or an 'Unknown' TaskState
>> (which was the fallback of most call sites anyway)
>>
>> Signed-off-by: Dominik Csapak <d.csapak@proxmox.com>
>> ---
>> we could save the error for later returning, but
>> since that does not matter most of the time i did not do that
>> but if wanted i can send a v2 or fixup for that
>>
>>   src/server/worker_task.rs | 17 ++++++++++++++---
>>   1 file changed, 14 insertions(+), 3 deletions(-)
>>
>> diff --git a/src/server/worker_task.rs b/src/server/worker_task.rs
>> index a9e4a36a..f6d12ac3 100644
>> --- a/src/server/worker_task.rs
>> +++ b/src/server/worker_task.rs
>> @@ -209,14 +209,25 @@ pub fn upid_read_status(upid: &UPID) -> Result<TaskState, Error> {
>>   
>>       let reader = BufReader::new(file);
>>   
>> +    let mut first_line = true;
>>       for line in reader.lines() {
>>           let line = line?;
>>   
>>           let mut iter = line.splitn(2, ": ");
>>           if let Some(time_str) = iter.next() {
>> -            endtime = chrono::DateTime::parse_from_rfc3339(time_str)
>> -                .map_err(|err| format_err!("cannot parse '{}': {}", time_str, err))?
>> -                .timestamp();
>> +            let dt_parse_res = chrono::DateTime::parse_from_rfc3339(time_str)
>> +                .map_err(|err| format_err!("cannot parse timestamp '{}': {}", time_str, err));
>> +            endtime = if first_line {
>> +                first_line = false;
>> +                match dt_parse_res {
>> +                    Ok(dt) => dt.timestamp(),
>> +                    // we maybe seeked into the middle of a line,
>> +                    // so ignore errors on the first
>> +                    Err(_) => continue,
>> +                }
>> +            } else {
>> +                dt_parse_res?.timestamp()
>> +            };
>>           } else {
>>               continue;
>>           }
>> -- 
>> 2.20.1
>>
>>
>>
>> _______________________________________________
>> pbs-devel mailing list
>> pbs-devel@lists.proxmox.com
>> https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel

Re: [pbs-devel] [PATCH proxmox-backup] server/worker_task: fix 'unknown' status for some big task logs

[Dietmar Maurer]

> no for two reasons:
> 
> if the task log contains only one line (this happens, e.g. 'TASK OK')
> or if the last Log line is exactly 8k long (i am not sure that could happen)
> 
> for the first we could check if the file is < 8k long

I committed a more optimized version:

diff --git a/src/server/worker_task.rs b/src/server/worker_task.rs
index a9e4a36..997c249 100644
--- a/src/server/worker_task.rs
+++ b/src/server/worker_task.rs
@@ -1,6 +1,6 @@
 use std::collections::HashMap;
 use std::fs::File;
-use std::io::{BufRead, BufReader};
+use std::io::{Read, BufRead, BufReader};
 use std::panic::UnwindSafe;
 use std::sync::atomic::{AtomicBool, Ordering};
 use std::sync::{Arc, Mutex};
@@ -195,8 +195,8 @@ pub fn create_task_log_dirs() -> Result<(), Error> {
 /// If there is not a single line with at valid datetime, we assume the
 /// starttime to be the endtime
 pub fn upid_read_status(upid: &UPID) -> Result<TaskState, Error> {
-    let mut endtime = upid.starttime;
-    let mut status = TaskState::Unknown { endtime };
+
+    let mut status = TaskState::Unknown { endtime: upid.starttime };
 
     let path = upid.log_path();
 
@@ -207,22 +207,29 @@ pub fn upid_read_status(upid: &UPID) -> Result<TaskState, Error> {
     use std::io::SeekFrom;
     let _ = file.seek(SeekFrom::End(-8192)); // ignore errors
 
-    let reader = BufReader::new(file);
-
-    for line in reader.lines() {
-        let line = line?;
+    let mut data = Vec::with_capacity(8192);
+    file.read_to_end(&mut data)?;
 
-        let mut iter = line.splitn(2, ": ");
-        if let Some(time_str) = iter.next() {
-            endtime = chrono::DateTime::parse_from_rfc3339(time_str)
-                .map_err(|err| format_err!("cannot parse '{}': {}", time_str, err))?
-                .timestamp();
-        } else {
-            continue;
+    let last_line = {
+        let mut start = 0;
+        for pos in data.len()-1..=0 {
+            if data[pos] == b'\n' {
+                start = pos + 1;
+                break;
+            }
         }
-        match iter.next().and_then(|rest| rest.strip_prefix("TASK ")) {
-            None => continue,
-            Some(rest) => {
+        &data[start..]
+    };
+
+    let last_line = std::str::from_utf8(last_line)
+        .map_err(|err| format_err!("upid_read_status: utf8 parse failed: {}", err))?;
+
+    let mut iter = last_line.splitn(2, ": ");
+    if let Some(time_str) = iter.next() {
+        if let Ok(endtime) = chrono::DateTime::parse_from_rfc3339(time_str) {
+            let endtime = endtime.timestamp();
+
+            if let Some(rest) = iter.next().and_then(|rest| rest.strip_prefix("TASK ")) {
                 if let Ok(state) = TaskState::from_endtime_and_message(endtime, rest) {
                     status = state;
                 }