timperproxy will just measure the time of queries, and formatting will be handled by the new sql_formatter of queries from sqlalchemy itself. Updated ini files for new way logging

development.ini

@@ -143,21 +143,21 b' logview.pylons.util = #eee'
 #########################################################
 #sqlalchemy.db1.url = sqlite:///%(here)s/rhodecode.db
 sqlalchemy.db1.url = postgresql://postgres:qwe@localhost/rhodecode
-#sqlalchemy.db1.echo = False
-#sqlalchemy.db1.pool_recycle = 3600
+sqlalchemy.db1.echo = True
+sqlalchemy.db1.pool_recycle = 3600
 sqlalchemy.convert_unicode = true
 
 ################################
 ### LOGGING CONFIGURATION   ####
 ################################
 [loggers]
-keys = root, routes, rhodecode, sqlalchemy,beaker,templates
+keys = root, routes, rhodecode, sqlalchemy, beaker, templates
 
 [handlers]
-keys = console
+keys = console, console_sql
 
 [formatters]
-keys = generic,color_formatter
+keys = generic, color_formatter, color_formatter_sql
 
 #############
 ## LOGGERS ##
@@ -168,32 +168,32 b' handlers = console'
 
 [logger_routes]
 level = DEBUG
-handlers = console
+handlers = 
 qualname = routes.middleware
 # "level = DEBUG" logs the route matched and routing variables.
-propagate = 0
+propagate = 1
 
 [logger_beaker]
-level = ERROR
-handlers = console
+level = DEBUG
+handlers = 
 qualname = beaker.container
-propagate = 0
+propagate = 1
 
 [logger_templates]
 level = INFO
-handlers = console
+handlers = 
 qualname = pylons.templating
-propagate = 0
+propagate = 1
 
 [logger_rhodecode]
 level = DEBUG
-handlers = console
+handlers = 
 qualname = rhodecode
-propagate = 0
+propagate = 1
 
 [logger_sqlalchemy]
-level = ERROR
-handlers = console
+level = INFO
+handlers = console_sql
 qualname = sqlalchemy.engine
 propagate = 0
 
@@ -207,6 +207,12 b' args = (sys.stderr,)'
 level = NOTSET
 formatter = color_formatter
 
+[handler_console_sql]
+class = StreamHandler
+args = (sys.stderr,)
+level = NOTSET
+formatter = color_formatter_sql
+
 ################
 ## FORMATTERS ##
 ################
@@ -218,4 +224,9 b' datefmt = %Y-%m-%d %H:%M:%S'
 [formatter_color_formatter]
 class=rhodecode.lib.colored_formatter.ColorFormatter
 format= %(asctime)s.%(msecs)03d %(levelname)-5.5s [%(name)s] %(message)s
+datefmt = %Y-%m-%d %H:%M:%S
+
+[formatter_color_formatter_sql]
+class=rhodecode.lib.colored_formatter.ColorFormatterSql
+format= %(asctime)s.%(msecs)03d %(levelname)-5.5s [%(name)s] %(message)s
 datefmt = %Y-%m-%d %H:%M:%S
  No newline at end of file

production.ini

@@ -29,7 +29,7 b' debug = true'
 threadpool_workers = 5
 
 ##max request before thread respawn
-threadpool_max_requests = 6
+threadpool_max_requests = 10
 
 ##option to use threads of process
 use_threadpool = true
@@ -41,13 +41,14 b' port = 8001'
 [app:main]
 use = egg:rhodecode
 full_stack = true
-static_files = false
+static_files = true
 lang=en
 cache_dir = %(here)s/data
 index_dir = %(here)s/data/index
+app_instance_uuid = prod1234
 cut_off_limit = 256000
-force_https = false
-commit_parse_limit = 25
+force_https = false 
+commit_parse_limit = 50
 use_gravatar = true
 
 ####################################
@@ -142,57 +143,57 b' logview.pylons.util = #eee'
 #########################################################
 #sqlalchemy.db1.url = sqlite:///%(here)s/rhodecode.db
 sqlalchemy.db1.url = postgresql://postgres:qwe@localhost/rhodecode
-#sqlalchemy.db1.echo = False
-#sqlalchemy.db1.pool_recycle = 3600
+sqlalchemy.db1.echo = True
+sqlalchemy.db1.pool_recycle = 3600
 sqlalchemy.convert_unicode = true
 
 ################################
 ### LOGGING CONFIGURATION   ####
 ################################
 [loggers]
-keys = root, routes, rhodecode, sqlalchemy,beaker,templates
+keys = root, routes, rhodecode, sqlalchemy, beaker, templates
 
 [handlers]
-keys = console
+keys = console, console_sql
 
 [formatters]
-keys = generic,color_formatter
+keys = generic, color_formatter, color_formatter_sql
 
 #############
 ## LOGGERS ##
 #############
 [logger_root]
-level = INFO
+level = NOTSET
 handlers = console
 
 [logger_routes]
-level = INFO
-handlers = console
+level = DEBUG
+handlers = 
 qualname = routes.middleware
 # "level = DEBUG" logs the route matched and routing variables.
-propagate = 0
+propagate = 1
 
 [logger_beaker]
-level = ERROR
-handlers = console
+level = DEBUG
+handlers = 
 qualname = beaker.container
-propagate = 0
+propagate = 1
 
 [logger_templates]
 level = INFO
-handlers = console
+handlers = 
 qualname = pylons.templating
-propagate = 0
+propagate = 1
 
 [logger_rhodecode]
 level = DEBUG
-handlers = console
+handlers = 
 qualname = rhodecode
-propagate = 0
+propagate = 1
 
 [logger_sqlalchemy]
-level = ERROR
-handlers = console
+level = INFO
+handlers = console_sql
 qualname = sqlalchemy.engine
 propagate = 0
 
@@ -203,9 +204,15 b' propagate = 0'
 [handler_console]
 class = StreamHandler
 args = (sys.stderr,)
-level = NOTSET
+level = INFO
 formatter = color_formatter
 
+[handler_console_sql]
+class = StreamHandler
+args = (sys.stderr,)
+level = WARN
+formatter = color_formatter_sql
+
 ################
 ## FORMATTERS ##
 ################
@@ -217,4 +224,9 b' datefmt = %Y-%m-%d %H:%M:%S'
 [formatter_color_formatter]
 class=rhodecode.lib.colored_formatter.ColorFormatter
 format= %(asctime)s.%(msecs)03d %(levelname)-5.5s [%(name)s] %(message)s
+datefmt = %Y-%m-%d %H:%M:%S
+
+[formatter_color_formatter_sql]
+class=rhodecode.lib.colored_formatter.ColorFormatterSql
+format= %(asctime)s.%(msecs)03d %(levelname)-5.5s [%(name)s] %(message)s
 datefmt = %Y-%m-%d %H:%M:%S
  No newline at end of file

rhodecode/config/deployment.ini_tmpl

@@ -142,57 +142,57 b' logview.pylons.util = #eee'
 ### DB CONFIGS - EACH DB WILL HAVE IT'S OWN CONFIG    ###
 #########################################################
 sqlalchemy.db1.url = sqlite:///%(here)s/rhodecode.db
-#sqlalchemy.db1.echo = False
-#sqlalchemy.db1.pool_recycle = 3600
+sqlalchemy.db1.echo = True
+sqlalchemy.db1.pool_recycle = 3600
 sqlalchemy.convert_unicode = true
 
 ################################
 ### LOGGING CONFIGURATION   ####
 ################################
 [loggers]
-keys = root, routes, rhodecode, sqlalchemy,beaker,templates
+keys = root, routes, rhodecode, sqlalchemy, beaker, templates
 
 [handlers]
-keys = console
+keys = console, console_sql
 
 [formatters]
-keys = generic,color_formatter
+keys = generic, color_formatter, color_formatter_sql
 
 #############
 ## LOGGERS ##
 #############
 [logger_root]
-level = INFO
+level = NOTSET
 handlers = console
 
 [logger_routes]
-level = INFO
-handlers = console
+level = DEBUG
+handlers = 
 qualname = routes.middleware
 # "level = DEBUG" logs the route matched and routing variables.
-propagate = 0
+propagate = 1
 
 [logger_beaker]
-level = ERROR
-handlers = console
+level = DEBUG
+handlers = 
 qualname = beaker.container
-propagate = 0
+propagate = 1
 
 [logger_templates]
 level = INFO
-handlers = console
+handlers = 
 qualname = pylons.templating
-propagate = 0
+propagate = 1
 
 [logger_rhodecode]
 level = DEBUG
-handlers = console
+handlers = 
 qualname = rhodecode
-propagate = 0
+propagate = 1
 
 [logger_sqlalchemy]
-level = ERROR
-handlers = console
+level = INFO
+handlers = console_sql
 qualname = sqlalchemy.engine
 propagate = 0
 
@@ -203,9 +203,15 b' propagate = 0'
 [handler_console]
 class = StreamHandler
 args = (sys.stderr,)
-level = NOTSET
+level = INFO
 formatter = color_formatter
 
+[handler_console_sql]
+class = StreamHandler
+args = (sys.stderr,)
+level = WARN
+formatter = color_formatter_sql
+
 ################
 ## FORMATTERS ##
 ################
@@ -217,4 +223,9 b' datefmt = %Y-%m-%d %H:%M:%S'
 [formatter_color_formatter]
 class=rhodecode.lib.colored_formatter.ColorFormatter
 format= %(asctime)s.%(msecs)03d %(levelname)-5.5s [%(name)s] %(message)s
+datefmt = %Y-%m-%d %H:%M:%S
+
+[formatter_color_formatter_sql]
+class=rhodecode.lib.colored_formatter.ColorFormatterSql
+format= %(asctime)s.%(msecs)03d %(levelname)-5.5s [%(name)s] %(message)s
 datefmt = %Y-%m-%d %H:%M:%S
  No newline at end of file

rhodecode/lib/colored_formatter.py

@@ -14,8 +14,35 b' COLORS = {'
     'WARNING': CYAN, # level 30
     'INFO': GREEN, # level 20
     'DEBUG': BLUE, # level 10
+    'SQL' : YELLOW
 }
 
+def one_space_trim(s):
+    if s.find("  ") == -1:
+        return s
+    else:
+        s = s.replace('  ', ' ')
+        return one_space_trim(s)
+
+def format_sql(sql):
+    sql = sql.replace('\n', '')
+    sql = one_space_trim(sql)
+    sql = sql\
+        .replace(',', ',\n\t')\
+        .replace('SELECT', '\n\tSELECT \n\t')\
+        .replace('UPDATE', '\n\tUPDATE \n\t')\
+        .replace('DELETE', '\n\tDELETE \n\t')\
+        .replace('FROM', '\n\tFROM')\
+        .replace('ORDER BY', '\n\tORDER BY')\
+        .replace('LIMIT', '\n\tLIMIT')\
+        .replace('WHERE', '\n\tWHERE')\
+        .replace('AND', '\n\tAND')\
+        .replace('LEFT', '\n\tLEFT')\
+        .replace('INNER', '\n\tINNER')\
+        .replace('INSERT', '\n\tINSERT')\
+        .replace('DELETE', '\n\tDELETE')
+    return sql
+
 class ColorFormatter(logging.Formatter):
 
     def __init__(self, *args, **kwargs):
@@ -26,13 +53,31 b' class ColorFormatter(logging.Formatter):'
         """
         Changes record's levelname to use with COLORS enum
         """
-        
+
         levelname = record.levelname
         start = COLOR_SEQ % (COLORS[levelname])
         def_record = logging.Formatter.format(self, record)
         end = RESET_SEQ
-        
+
         colored_record = start + def_record + end
         return colored_record
 
-logging.ColorFormatter = ColorFormatter
+
+class ColorFormatterSql(logging.Formatter):
+
+    def __init__(self, *args, **kwargs):
+        # can't do super(...) here because Formatter is an old school class
+        logging.Formatter.__init__(self, *args, **kwargs)
+
+    def format(self, record):
+        """
+        Changes record's levelname to use with COLORS enum
+        """
+
+        start = COLOR_SEQ % (COLORS['SQL'])
+        def_record = format_sql(logging.Formatter.format(self, record))
+        end = RESET_SEQ
+
+        colored_record = start + def_record + end
+        return colored_record
+

rhodecode/lib/timerproxy.py

@@ -7,53 +7,22 b' def color_sql(sql):'
     COLOR_SEQ = "\033[1;%dm"
     COLOR_SQL = YELLOW
     normal = '\x1b[0m'
-    return COLOR_SEQ % COLOR_SQL + sql + normal 
-
-def one_space_trim(s):
-    if s.find("  ") == -1:
-        return s
-    else:
-        s = s.replace('  ', ' ')
-        return one_space_trim(s)
-    
-def format_sql(sql):
-    sql = color_sql(sql)
-    sql = sql.replace('\n', '')
-    sql = one_space_trim(sql)
-    sql = sql\
-        .replace(',', ',\n\t')\
-        .replace('SELECT', '\n\tSELECT \n\t')\
-        .replace('UPDATE', '\n\tUPDATE \n\t')\
-        .replace('DELETE', '\n\tDELETE \n\t')\
-        .replace('FROM', '\n\tFROM')\
-        .replace('ORDER BY', '\n\tORDER BY')\
-        .replace('LIMIT', '\n\tLIMIT')\
-        .replace('WHERE', '\n\tWHERE')\
-        .replace('AND', '\n\tAND')\
-        .replace('LEFT', '\n\tLEFT')\
-        .replace('INNER', '\n\tINNER')\
-        .replace('INSERT', '\n\tINSERT')\
-        .replace('DELETE', '\n\tDELETE')
-    return sql
-
+    return COLOR_SEQ % COLOR_SQL + sql + normal
 
 class TimerProxy(ConnectionProxy):
-    
+
     def __init__(self):
         super(TimerProxy, self).__init__()
         self.logging_name = 'timerProxy'
         self.log = log.instance_logger(self, True)
-        
-    def cursor_execute(self, execute, cursor, statement, parameters, context, executemany):
-        
+
+    def cursor_execute(self, execute, cursor, statement, parameters,
+                       context, executemany):
+
         now = time.time()
         try:
-            self.log.info(">>>>> STARTING QUERY >>>>>")
+            self.log.info(color_sql(">>>>> STARTING QUERY >>>>>"))
             return execute(cursor, statement, parameters, context)
         finally:
             total = time.time() - now
-            try:
-                self.log.info(format_sql("Query: %s" % statement % parameters))
-            except TypeError:
-                self.log.info(format_sql("Query: %s %s" % (statement, parameters)))
-            self.log.info("<<<<< TOTAL TIME: %f <<<<<" % total)
+            self.log.info(color_sql("<<<<< TOTAL TIME: %f <<<<<" % total))