From c795e5258a620fa14b59eedd44e11d26148efe76 Mon Sep 17 00:00:00 2001
From: Auroir <36361058+Auroir@users.noreply.github.com>
Date: Fri, 16 Aug 2019 16:06:47 -0700
Subject: [PATCH] Fix log_info/log_err printing with progress bars

**Issue**
While a TQDM progress bar is active using a standard 'print' will cause unpredicable output. In most cases this causes the progress bar to be duplicated/frozen next to the log message:
```
Running on CPU0.
Running on CPU1.
Converting:   0% 0/356 [00:00<?, ?it/s]no faces found for 00001.png, copying without faces
Converting:   0% 1/356 [00:00<00:02, 165.12it/s]no faces found for 00002.png, copying without faces
Converting:   1% 2/356 [00:00<00:01, 318.97it/s]no faces found for 00003.png, copying without faces
Converting:   1% 3/356 [00:00<00:01, 255.22it/s]no faces found for 00004.png, copying without faces
Converting:   1% 4/356 [00:00<00:01, 333.46it/s]no faces found for 00005.png, copying without faces
Converting:   1% 5/356 [00:00<00:01, 287.34it/s]no faces found for 00006.png, copying without faces
Converting:   2% 6/356 [00:00<00:01, 340.82it/s]no faces found for 00007.png, copying without faces
Converting:   2% 7/356 [00:00<00:01, 301.00it/s]no faces found for 00008.png, copying without faces
Converting:   2% 8/356 [00:00<00:01, 341.15it/s]no faces found for 00009.png, copying without faces
Converting:   3% 9/356 [00:00<00:01, 310.79it/s]no faces found for 00010.png, copying without faces
Converting:   3% 10/356 [00:00<00:01, 342.98it/s]no faces found for 00011.png, copying without faces
Converting:   3% 11/356 [00:00<00:01, 317.86it/s]no faces found for 00012.png, copying without faces
Converting:   3% 12/356 [00:00<00:00, 344.40it/s]no faces found for 00013.png, copying without faces
Converting:   4% 13/356 [00:00<00:01, 322.13it/s]no faces found for 00014.png, copying without faces
```
**Resolution**
This can be mitigated by changing `log_info` and `log_err` to be aware of the presence of a progress bar and use `tqdm.write()` instead of `print()` if one exists:
```
Running on CPU0.
Running on CPU1.
no faces found for 00001.png, copying without faces
no faces found for 00002.png, copying without faces
no faces found for 00003.png, copying without faces
no faces found for 00004.png, copying without faces
no faces found for 00005.png, copying without faces
...
no faces found for 00197.png, copying without faces
no faces found for 00198.png, copying without faces
no faces found for 00199.png, copying without faces
Converting:  57% 203/356 [00:01<00:01, 120.22it/s]
```
**Method**
For `log_info` if a pb is running `tqdm.write` is attempted, if it fails a normal print is used. Likewise with `log_err` except that the msg is prefixed by `self.error_log_line_prefix`, `/!\`, to denote increased severity.

`progress_bar_generator()` has been updated to set `self.pb_bar` like the `progress_bar()` function and then clean up when the generator expires. Without this the class is unaware of the running pb since `self.pb_bar` remains defaulted to `None`.

**Result**
This doesn't completely fix the problem, there is still a lot of normal `print()` calls that will need to be updated eventually to use these for printing.
```
Loading:   3% 30/1000 [00:00<00:03, 297.17it/s]No Valid PNG header
00100.png is not a dfl image file required for training
Loading:  13% 126/1000 [00:00<00:02, 374.53it/s]No Valid PNG header
00200.png is not a dfl image file required for training
Loading:  30% 296/1000 [00:00<00:01, 519.82it/s]No Valid PNG header
00300.png is not a dfl image file required for training
Loading:  38% 380/1000 [00:00<00:01, 586.20it/s]No Valid PNG header
00400.png is not a dfl image file required for training
```
`No Valid PNG header` has not been updated to use `log_info`, causes duplicate progress bars. `<X> is not a dfl image file required for training` does use `log_info` and prints correctly. A majority of the commonly seen messages are covered, so this is still very worthwhile from a UX perspective.
---
 interact/interact.py | 22 +++++++++++++++++++---
 1 file changed, 19 insertions(+), 3 deletions(-)

diff --git a/interact/interact.py b/interact/interact.py
index c9b22f1..bda74af 100644
--- a/interact/interact.py
+++ b/interact/interact.py
@@ -33,6 +33,7 @@ class InteractBase(object):
         self.key_events = {}
         self.pg_bar = None
         self.focus_wnd_name = None
+        self.error_log_line_prefix = '/!\\ '
 
     def is_support_windows(self):
         return False
@@ -65,10 +66,22 @@ class InteractBase(object):
         raise NotImplemented
 
     def log_info(self, msg, end='\n'):
+        if self.pg_bar is not None:
+            try: # Attempt print before the pb
+                tqdm.write(msg)
+                return
+            except: 
+                pass #Fallback to normal print upon failure
         print (msg, end=end)
 
     def log_err(self, msg, end='\n'):
-        print (msg, end=end)
+        if self.pg_bar is not None:
+            try: # Attempt print before the pb
+                tqdm.write(f'{self.error_log_line_prefix}{msg}')
+                return
+            except: 
+                pass #Fallback to normal print upon failure
+        print (f'{self.error_log_line_prefix}{msg}', end=end)
 
     def named_window(self, wnd_name):
         if wnd_name not in self.named_windows:
@@ -150,9 +163,12 @@ class InteractBase(object):
         else: print("progress_bar not set.")
 
     def progress_bar_generator(self, data, desc, leave=True):
-        for x in tqdm( data, desc=desc, leave=leave, ascii=True ):
+        self.pg_bar = tqdm( data, desc=desc, leave=leave, ascii=True )
+        for x in self.pg_bar:
             yield x
-
+        self.pg_bar.close()   
+        self.pg_bar = None
+        
     def process_messages(self, sleep_time=0):
         self.on_process_messages(sleep_time)