← Back to branch summary

~openerp-dev/openobject-server/trunk-imp-onchange-behave-darshan

« back to all changes in this revision

Viewing changes to openerp/netsvc.py

  • Committer: Darshan Kalola(OpenERP)
  • Date: 2014-04-09 08:44:52 UTC
  • mfrom: (4936.1.232 openobject-server)
  • Revision ID: dka@tinyerp.com-20140409084452-w1e499j21i3eli9d
[MERGE]sync with trunk.

Show diffs side-by-side

added added

removed removed

Lines of Context:
openerp/netsvc.py
2
2
##############################################################################
3
3
#
4
4
#    OpenERP, Open Source Management Solution
5
 
#    Copyright (C) 2004-2012 OpenERP SA (<http://www.openerp.com>)
 
5
#    Copyright (C) 2004-2014 OpenERP SA (<http://www.openerp.com>)
6
6
#
7
7
#    This program is free software: you can redistribute it and/or modify
8
8
#    it under the terms of the GNU Affero General Public License as
19
19
#
20
20
##############################################################################
21
21
 
22
 
 
23
22
import logging
24
23
import logging.handlers
25
24
import os
 
25
import pprint
26
26
import release
27
27
import sys
28
28
import threading
29
 
import time
30
 
import types
31
 
from pprint import pformat
32
 
import psutil
33
 
 
 
29
 
 
30
import psycopg2
 
31
 
 
32
import openerp
 
33
import sql_db
34
34
import tools
35
 
import openerp
36
35
 
37
36
_logger = logging.getLogger(__name__)
38
37
 
 
38
def log(logger, level, prefix, msg, depth=None):
 
39
    indent=''
 
40
    indent_after=' '*len(prefix)
 
41
    for line in (prefix + pprint.pformat(msg, depth=depth)).split('\n'):
 
42
        logger.log(level, indent+line)
 
43
        indent=indent_after
 
44
 
39
45
def LocalService(name):
40
46
    """
41
47
    The openerp.netsvc.LocalService() function is deprecated. It still works
62
68
                with registry.cursor() as cr:
63
69
                    return registry['ir.actions.report.xml']._lookup_report(cr, name[len('report.'):])
64
70
 
 
71
class PostgreSQLHandler(logging.Handler):
 
72
    """ PostgreSQL Loggin Handler will store logs in the database, by default
 
73
    the current database, can be set using --log-db=DBNAME
 
74
    """
 
75
    def emit(self, record):
 
76
        ct = threading.current_thread()
 
77
        ct_db = getattr(ct, 'dbname', None)
 
78
        ct_uid = getattr(ct, 'uid', None)
 
79
        dbname = tools.config['log_db'] or ct_db
 
80
        if dbname:
 
81
            cr = None
 
82
            try:
 
83
                cr = sql_db.db_connect(dbname).cursor()
 
84
                msg = unicode(record.msg)
 
85
                traceback = getattr(record, 'exc_text', '')
 
86
                if traceback:
 
87
                    msg = "%s\n%s" % (msg, traceback)
 
88
                level = logging.getLevelName(record.levelno)
 
89
                val = (ct_uid, ct_uid, 'server', dbname, record.name, level, msg, record.pathname, record.lineno, record.funcName)
 
90
                cr.execute("""
 
91
                    INSERT INTO ir_logging(create_date, write_date, create_uid, write_uid, type, dbname, name, level, message, path, line, func)
 
92
                    VALUES (NOW() at time zone 'UTC', NOW() at time zone 'UTC', %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)
 
93
                """, val )
 
94
                cr.commit()
 
95
            except Exception, e:
 
96
                pass
 
97
            finally:
 
98
                if cr:
 
99
                    cr.close()
 
100
 
65
101
BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE, _NOTHING, DEFAULT = range(10)
66
102
#The background is set with 40 plus the number of the color, and the foreground with 30
67
103
#These are the sequences need to get colored ouput
89
125
        record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
90
126
        return DBFormatter.format(self, record)
91
127
 
 
128
_logger_init = False
92
129
def init_logger():
 
130
    global _logger_init
 
131
    if _logger_init:
 
132
        return
 
133
    _logger_init = True
 
134
 
93
135
    from tools.translate import resetlocale
94
136
    resetlocale()
95
137
 
101
143
        if os.name == 'nt':
102
144
            handler = logging.handlers.NTEventLogHandler("%s %s" % (release.description, release.version))
103
145
        else:
104
 
            handler = logging.handlers.SysLogHandler('/dev/log')
 
146
            handler = logging.handlers.SysLogHandler()
105
147
        format = '%s %s' % (release.description, release.version) \
106
148
                + ':%(dbname)s:%(levelname)s:%(name)s:%(message)s'
107
149
 
109
151
        # LogFile Handler
110
152
        logf = tools.config['logfile']
111
153
        try:
 
154
            # We check we have the right location for the log files
112
155
            dirname = os.path.dirname(logf)
113
156
            if dirname and not os.path.isdir(dirname):
114
157
                os.makedirs(dirname)
115
158
            if tools.config['logrotate'] is not False:
116
 
                handler = logging.handlers.TimedRotatingFileHandler(logf,'D',1,30)
 
159
                handler = logging.handlers.TimedRotatingFileHandler(filename=logf, when='D', interval=1, backupCount=30)
117
160
            elif os.name == 'posix':
118
161
                handler = logging.handlers.WatchedFileHandler(logf)
119
162
            else:
129
172
    # behind Apache with mod_wsgi, handler.stream will have type mod_wsgi.Log,
130
173
    # which has no fileno() method. (mod_wsgi.Log is what is being bound to
131
174
    # sys.stderr when the logging.StreamHandler is being constructed above.)
132
 
    if isinstance(handler, logging.StreamHandler) \
133
 
        and hasattr(handler.stream, 'fileno') \
134
 
        and os.isatty(handler.stream.fileno()):
 
175
    def is_a_tty(stream):
 
176
        return hasattr(stream, 'fileno') and os.isatty(stream.fileno())
 
177
 
 
178
    if isinstance(handler, logging.StreamHandler) and is_a_tty(handler.stream):
135
179
        formatter = ColoredFormatter(format)
136
180
    else:
137
181
        formatter = DBFormatter(format)
138
182
    handler.setFormatter(formatter)
139
183
 
140
 
    # Configure handlers
 
184
    logging.getLogger().addHandler(handler)
 
185
 
 
186
    if tools.config['log_db']:
 
187
        postgresqlHandler = PostgreSQLHandler()
 
188
        postgresqlHandler.setLevel(logging.WARNING)
 
189
        logging.getLogger().addHandler(postgresqlHandler)
 
190
 
 
191
    # Configure loggers levels
141
192
    pseudo_config = PSEUDOCONFIG_MAPPER.get(tools.config['log_level'], [])
142
193
 
143
194
    logconfig = tools.config['log_handler']
147
198
        loggername, level = logconfig_item.split(':')
148
199
        level = getattr(logging, level, logging.INFO)
149
200
        logger = logging.getLogger(loggername)
150
 
        logger.handlers = []
151
201
        logger.setLevel(level)
152
 
        logger.addHandler(handler)
153
 
        if loggername != '':
154
 
            logger.propagate = False
155
202
 
156
203
    for logconfig_item in logging_configurations:
157
204
        _logger.debug('logger level set: "%s"', logconfig_item)
158
205
 
159
206
DEFAULT_LOG_CONFIGURATION = [
160
207
    'openerp.workflow.workitem:WARNING',
161
 
    'openerp.netsvc.rpc.request:INFO',
162
 
    'openerp.netsvc.rpc.response:INFO',
 
208
    'openerp.http.rpc.request:INFO',
 
209
    'openerp.http.rpc.response:INFO',
163
210
    'openerp.addons.web.http:INFO',
164
211
    'openerp.sql_db:INFO',
165
212
    ':INFO',
166
213
]
167
214
PSEUDOCONFIG_MAPPER = {
168
 
    'debug_rpc_answer': ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG', 'openerp.netsvc.rpc.response:DEBUG'],
169
 
    'debug_rpc': ['openerp:DEBUG','openerp.netsvc.rpc.request:DEBUG'],
 
215
    'debug_rpc_answer': ['openerp:DEBUG','openerp.http.rpc.request:DEBUG', 'openerp.http.rpc.response:DEBUG'],
 
216
    'debug_rpc': ['openerp:DEBUG','openerp.http.rpc.request:DEBUG'],
170
217
    'debug': ['openerp:DEBUG'],
171
218
    'debug_sql': ['openerp.sql_db:DEBUG'],
172
219
    'info': [],
175
222
    'critical': ['openerp:CRITICAL'],
176
223
}
177
224
 
178
 
# A alternative logging scheme for automated runs of the
179
 
# server intended to test it.
180
 
def init_alternative_logger():
181
 
    class H(logging.Handler):
182
 
        def emit(self, record):
183
 
            if record.levelno > 20:
184
 
                print record.levelno, record.pathname, record.msg
185
 
    handler = H()
186
 
    # Add the handler to the 'openerp' logger.
187
 
    logger = logging.getLogger('openerp')
188
 
    logger.addHandler(handler)
189
 
    logger.setLevel(logging.ERROR)
190
 
 
191
 
def replace_request_password(args):
192
 
    # password is always 3rd argument in a request, we replace it in RPC logs
193
 
    # so it's easier to forward logs for diagnostics/debugging purposes...
194
 
    if len(args) > 2:
195
 
        args = list(args)
196
 
        args[2] = '*'
197
 
    return tuple(args)
198
 
 
199
 
def log(logger, level, prefix, msg, depth=None):
200
 
    indent=''
201
 
    indent_after=' '*len(prefix)
202
 
    for line in (prefix+pformat(msg, depth=depth)).split('\n'):
203
 
        logger.log(level, indent+line)
204
 
        indent=indent_after
205
 
 
206
 
def dispatch_rpc(service_name, method, params):
207
 
    """ Handle a RPC call.
208
 
 
209
 
    This is pure Python code, the actual marshalling (from/to XML-RPC) is done
210
 
    in a upper layer.
211
 
    """
212
 
    try:
213
 
        rpc_request = logging.getLogger(__name__ + '.rpc.request')
214
 
        rpc_response = logging.getLogger(__name__ + '.rpc.response')
215
 
        rpc_request_flag = rpc_request.isEnabledFor(logging.DEBUG)
216
 
        rpc_response_flag = rpc_response.isEnabledFor(logging.DEBUG)
217
 
        if rpc_request_flag or rpc_response_flag:
218
 
            start_time = time.time()
219
 
            start_rss, start_vms = 0, 0
220
 
            start_rss, start_vms = psutil.Process(os.getpid()).get_memory_info()
221
 
            if rpc_request and rpc_response_flag:
222
 
                log(rpc_request,logging.DEBUG,'%s.%s'%(service_name,method), replace_request_password(params))
223
 
 
224
 
        threading.current_thread().uid = None
225
 
        threading.current_thread().dbname = None
226
 
        if service_name == 'common':
227
 
            dispatch = openerp.service.common.dispatch
228
 
        elif service_name == 'db':
229
 
            dispatch = openerp.service.db.dispatch
230
 
        elif service_name == 'object':
231
 
            dispatch = openerp.service.model.dispatch
232
 
        elif service_name == 'report':
233
 
            dispatch = openerp.service.report.dispatch
234
 
        else:
235
 
            dispatch = openerp.service.wsgi_server.rpc_handlers.get(service_name)
236
 
        result = dispatch(method, params)
237
 
 
238
 
        if rpc_request_flag or rpc_response_flag:
239
 
            end_time = time.time()
240
 
            end_rss, end_vms = 0, 0
241
 
            end_rss, end_vms = psutil.Process(os.getpid()).get_memory_info()
242
 
            logline = '%s.%s time:%.3fs mem: %sk -> %sk (diff: %sk)' % (service_name, method, end_time - start_time, start_vms / 1024, end_vms / 1024, (end_vms - start_vms)/1024)
243
 
            if rpc_response_flag:
244
 
                log(rpc_response,logging.DEBUG, logline, result)
245
 
            else:
246
 
                log(rpc_request,logging.DEBUG, logline, replace_request_password(params), depth=1)
247
 
 
248
 
        return result
249
 
    except openerp.osv.orm.except_orm:
250
 
        raise
251
 
    except openerp.exceptions.AccessError:
252
 
        raise
253
 
    except openerp.exceptions.AccessDenied:
254
 
        raise
255
 
    except openerp.exceptions.Warning:
256
 
        raise
257
 
    except openerp.exceptions.RedirectWarning:
258
 
        raise
259
 
    except openerp.exceptions.DeferredException, e:
260
 
        _logger.exception(tools.exception_to_unicode(e))
261
 
        post_mortem(e.traceback)
262
 
        raise
263
 
    except Exception, e:
264
 
        _logger.exception(tools.exception_to_unicode(e))
265
 
        post_mortem(sys.exc_info())
266
 
        raise
267
 
 
268
 
def post_mortem(info):
269
 
    if tools.config['debug_mode'] and isinstance(info[2], types.TracebackType):
270
 
        import pdb
271
 
        pdb.post_mortem(info[2])
272
 
 
273
225
# vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: