BlenderKit: switch to logging for the add-on

This should help with sane development and also avoid forgotten prints for users.

8 files changed, 44 insertions, 36 deletions

diff --git a/blenderkit/__init__.py b/blenderkit/__init__.py
index dd04c506..84cabcfe 100644
--- a/blenderkit/__init__.py
+++ b/blenderkit/__init__.py
@@ -56,10 +56,13 @@ else:
 import os
 import math
 import time
-# import logging
+import logging
 import bpy
 import pathlib
 
+log = logging.getLogger(__name__)
+
+
 from bpy.app.handlers import persistent
 import bpy.utils.previews
 import mathutils
diff --git a/blenderkit/ratings.py b/blenderkit/ratings.py
index d2c91412..57c38087 100644
--- a/blenderkit/ratings.py
+++ b/blenderkit/ratings.py
@@ -400,7 +400,6 @@ class FastRateMenu(Operator):
         col.prop(self, 'rating_work_hours')
         if utils.profile_is_validator():
             row = layout.row()
-            print(self.asset_type, ' asset type for rating')
             if self.asset_type == 'model':
                 row.prop(self, 'rating_work_hours_ui', expand=True, icon_only=False, emboss=True)
             else:
diff --git a/blenderkit/rerequests.py b/blenderkit/rerequests.py
index 25f693d7..7671f3cf 100644
--- a/blenderkit/rerequests.py
+++ b/blenderkit/rerequests.py
@@ -29,6 +29,8 @@ else:
 
 import requests
 import bpy
+import logging
+bk_logger = logging.getLogger('rerequests')
 
 
 def rerequest(method, url, **kwargs):
@@ -40,8 +42,8 @@ def rerequest(method, url, **kwargs):
     # first normal attempt
     response = requests.request(method, url, **kwargs)
 
-    utils.p(url, kwargs)
-    utils.p(response.status_code)
+    bk_logger.debug(url+ str( kwargs))
+    bk_logger.debug(response.status_code)
 
     if response.status_code == 401:
         try:
@@ -61,7 +63,7 @@ def rerequest(method, url, **kwargs):
                     auth_token, refresh_token, oauth_response = bkit_oauth.refresh_token(
                         user_preferences.api_key_refresh, refresh_url)
 
-                    # utils.p(auth_token, refresh_token)
+                    # bk_logger.debug(auth_token, refresh_token)
                     if auth_token is not None:
                         if immediate == True:
                             # this can write tokens occasionally into prefs. used e.g. in upload. Only possible
@@ -73,9 +75,9 @@ def rerequest(method, url, **kwargs):
 
                         kwargs['headers'] = utils.get_headers(auth_token)
                         response = requests.request(method, url, **kwargs)
-                        utils.p('reresult', response.status_code)
+                        bk_logger.debug('reresult', response.status_code)
                         if response.status_code >= 400:
-                            utils.p('reresult', response.text)
+                            bk_logger.debug('reresult', response.text)
                             tasks_queue.add_task((ui.add_report, (
                                 response.text, 10)))
 
diff --git a/blenderkit/search.py b/blenderkit/search.py
index 84254434..b1e62a7e 100644
--- a/blenderkit/search.py
+++ b/blenderkit/search.py
@@ -63,6 +63,9 @@ import copy
 import json
 import math
 
+import logging
+bk_logger = logging.getLogger('blenderkit')
+
 search_start_time = 0
 prev_time = 0
 
@@ -119,7 +122,7 @@ def update_ad(ad):
             ad['author']['id'] = ad['author_id']  # this should stay ONLY for compatibility with older scenes
             ad['canDownload'] = ad['can_download']  # this should stay ONLY for compatibility with older scenes
         except Exception as e:
-            print('BLenderKit failed to update older asset data')
+            bk_logger.error('BLenderKit failed to update older asset data')
     return ad
 
 
@@ -419,7 +422,7 @@ def timer_update():
                 bpy.ops.wm.undo_push_context(message='Get BlenderKit search')
 
             else:
-                print('error', error)
+                bk_logger.error(error)
                 props.report = error
                 props.search_error = True
 
@@ -671,7 +674,7 @@ def generate_tooltip(mdata):
             t += f"Hours saved rating: {int(mdata['ratingsAverage']['workingHours'])}\n"
         if utils.profile_is_validator():
             t += f"Ratings count {rc['quality']}*/{rc['workingHours']}wh value " \
-                 f"{int(mdata['ratingsAverage']['quality'])}*/{int(mdata['ratingsAverage']['workingHours'])}wh\n"
+                 f"{mdata['ratingsAverage']['quality']}*/{mdata['ratingsAverage']['workingHours']}wh\n"
     if len(t.split('\n')) < 11:
         t += '\n'
         t += get_random_tip(mdata)
@@ -822,7 +825,7 @@ def get_author(r):
 
 
 def write_profile(adata):
-    utils.p('writing profile')
+    utils.p('writing profile information')
     user = adata['user']
     # we have to convert to MiB here, numbers too big for python int type
     if user.get('sumAssetFilesSize') is not None:
@@ -855,11 +858,12 @@ def request_profile(api_key):
 def fetch_profile(api_key):
     utils.p('fetch profile')
     try:
+        gagf
         adata = request_profile(api_key)
         if adata is not None:
             tasks_queue.add_task((write_profile, (adata,)))
     except Exception as e:
-        utils.p(e)
+        bk_logger.error(e)
 
 
 def get_profile():
@@ -957,16 +961,16 @@ class Searcher(threading.Thread):
             reports = ''
             # utils.p(r.text)
         except requests.exceptions.RequestException as e:
-            print(e)
+            bk_logger.error(e)
             reports = e
             # props.report = e
             return
         mt('search response is back ')
         try:
             rdata = r.json()
-        except Exception as inst:
+        except Exception as e:
             reports = r.text
-            print(inst)
+            bk_logger.error(e)
 
         mt('data parsed ')
         if not rdata.get('results'):
@@ -1293,7 +1297,7 @@ def get_search_simple(parameters, filepath=None, page_size=100, max_results=1000
         requeststring += f'+{p}:{parameters[p]}'
 
     requeststring += '&page_size=' + str(page_size)
-    print(requeststring)
+    bk_logger.debug(requeststring)
     response = rerequests.get(requeststring, headers=headers)  # , params = rparameters)
     # print(r.json())
     search_results = response.json()
@@ -1303,7 +1307,7 @@ def get_search_simple(parameters, filepath=None, page_size=100, max_results=1000
     page_index = 2
     page_count = math.ceil(search_results['count'] / page_size)
     while search_results.get('next') and len(results) < max_results:
-        print(f'getting page {page_index} , total pages {page_count}')
+        bk_logger.info(f'getting page {page_index} , total pages {page_count}')
         response = rerequests.get(search_results['next'], headers=headers)  # , params = rparameters)
         search_results = response.json()
         # print(search_results)
@@ -1315,7 +1319,7 @@ def get_search_simple(parameters, filepath=None, page_size=100, max_results=1000
 
     with open(filepath, 'w') as s:
         json.dump(results, s)
-    print(f'retrieved {len(results)} assets from elastic search')
+    bk_logger.info(f'retrieved {len(results)} assets from elastic search')
     return results
 
 
diff --git a/blenderkit/tasks_queue.py b/blenderkit/tasks_queue.py
index 21eba33b..b6f45f3e 100644
--- a/blenderkit/tasks_queue.py
+++ b/blenderkit/tasks_queue.py
@@ -27,6 +27,8 @@ import bpy
 from bpy.app.handlers import persistent
 
 import queue
+import logging
+bk_logger = logging.getLogger('blenderkit')
 
 @persistent
 def scene_load(context):
@@ -81,7 +83,7 @@ def queue_worker():
         else:
             back_to_queue.append(task)
     if len(stashed.keys())>1:
-        print(stashed)
+        utils.p('task queue stashed task:', stashed)
     #return tasks to que except for stashed
     for task in back_to_queue:
         q.put(task)
@@ -98,8 +100,7 @@ def queue_worker():
             task.wait-=time_step
             back_to_queue.append(task)
         else:
-            utils.p('as a task:   ')
-            utils.p(task.command, task.arguments)
+            utils.p('task queue task:', task.command, task.arguments)
             try:
                 if task.fake_context:
                     fc = utils.get_fake_context(bpy.context, area_type = task.fake_context_area)
@@ -107,8 +108,7 @@ def queue_worker():
                 else:
                     task.command(*task.arguments)
             except Exception as e:
-                utils.p('task failed:')
-                print(e)
+                bk_logger.error('task queue failed task:'+ str(e))
         # print('queue while 2')
     for task in back_to_queue:
         q.put(task)
diff --git a/blenderkit/ui.py b/blenderkit/ui.py
index ba98f0cd..8acd9554 100644
--- a/blenderkit/ui.py
+++ b/blenderkit/ui.py
@@ -51,6 +51,9 @@ import time
 import datetime
 import os
 
+import logging
+bk_logger = logging.getLogger('blenderkit')
+
 handler_2d = None
 handler_3d = None
 active_area_pointer = None
@@ -1630,8 +1633,7 @@ class AssetBarOperator(bpy.types.Operator):
             # delete downloaded files for this asset
             sr = bpy.context.scene['search results']
             asset_data = sr[ui_props.active_index]
-            print(asset_data['name'])
-            print('delete')
+            bk_logger.info('delete asset from local drive:' + asset_data['name'])
             paths.delete_asset_debug(asset_data)
             asset_data['downloaded'] = 0
             return {'RUNNING_MODAL'}
diff --git a/blenderkit/upload_bg.py b/blenderkit/upload_bg.py
index 74ae8906..4fc96ffb 100644
--- a/blenderkit/upload_bg.py
+++ b/blenderkit/upload_bg.py
@@ -39,14 +39,6 @@ import bpy
 BLENDERKIT_EXPORT_DATA = sys.argv[-1]
 
 
-def start_logging():
-    logging.basicConfig()
-    logging.getLogger().setLevel(logging.DEBUG)
-    requests_log = logging.getLogger("requests.packages.urllib3")
-    requests_log.setLevel(logging.DEBUG)
-    requests_log.propagate = True
-
-
 def print_gap():
     print('\n\n\n\n')
 
diff --git a/blenderkit/utils.py b/blenderkit/utils.py
index 1bcb4c9b..ef3b5da6 100644
--- a/blenderkit/utils.py
+++ b/blenderkit/utils.py
@@ -32,6 +32,7 @@ import json
 import os
 import sys
 import shutil
+import logging
 
 ABOVE_NORMAL_PRIORITY_CLASS = 0x00008000
 BELOW_NORMAL_PRIORITY_CLASS = 0x00004000
@@ -379,11 +380,16 @@ def get_brush_props(context):
 def p(text, text1='', text2='', text3='', text4='', text5=''):
     '''debug printing depending on blender's debug value'''
 
-    if bpy.app.debug_value != 0:
-        print('\n')
+    if 1:#bpy.app.debug_value != 0:
         # print('-----BKit debug-----\n')
         # traceback.print_stack()
-        print(text, text1, text2, text3, text4, text5)
+        texts = [text1,text2,text3,text4,text5]
+        text = str(text)
+        for t in texts:
+            if t!= '':
+                text += ' ' + str(t)
+        bk_logger = logging.getLogger('blenderkit')
+        bk_logger.debug(text)
         # print('---------------------\n')