[IMP] use logging in db initialization
[odoo/odoo.git] / openerp / modules / loading.py
1 # -*- coding: utf-8 -*-
2 ##############################################################################
3 #
4 #    OpenERP, Open Source Management Solution
5 #    Copyright (C) 2004-2009 Tiny SPRL (<http://tiny.be>).
6 #    Copyright (C) 2010-2011 OpenERP s.a. (<http://openerp.com>).
7 #
8 #    This program is free software: you can redistribute it and/or modify
9 #    it under the terms of the GNU Affero General Public License as
10 #    published by the Free Software Foundation, either version 3 of the
11 #    License, or (at your option) any later version.
12 #
13 #    This program is distributed in the hope that it will be useful,
14 #    but WITHOUT ANY WARRANTY; without even the implied warranty of
15 #    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
16 #    GNU Affero General Public License for more details.
17 #
18 #    You should have received a copy of the GNU Affero General Public License
19 #    along with this program.  If not, see <http://www.gnu.org/licenses/>.
20 #
21 ##############################################################################
22
23 """ Modules (also called addons) management.
24
25 """
26
27 import os, sys, imp
28 from os.path import join as opj
29 import itertools
30 import zipimport
31
32 import openerp
33
34 import openerp.osv as osv
35 import openerp.tools as tools
36 import openerp.tools.osutil as osutil
37 from openerp.tools.safe_eval import safe_eval as eval
38 import openerp.pooler as pooler
39 from openerp.tools.translate import _
40
41 import openerp.netsvc as netsvc
42
43 import zipfile
44 import openerp.release as release
45
46 import re
47 import base64
48 from zipfile import PyZipFile, ZIP_DEFLATED
49 from cStringIO import StringIO
50
51 import logging
52
53 import openerp.modules.db
54 import openerp.modules.graph
55 import openerp.modules.migration
56
57 from openerp.modules.module import \
58     get_modules, get_modules_with_version, \
59     load_information_from_description_file, \
60     get_module_resource, zip_directory, \
61     get_module_path, initialize_sys_path, \
62     register_module_classes, init_module_models
63
64 logger = netsvc.Logger()
65
66
67 def open_openerp_namespace():
68     # See comment for open_openerp_namespace.
69     if openerp.conf.deprecation.open_openerp_namespace:
70         for k, v in list(sys.modules.items()):
71             if k.startswith('openerp.') and sys.modules.get(k[8:]) is None:
72                 sys.modules[k[8:]] = v
73
74
75 def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules=None, report=None):
76     """Migrates+Updates or Installs all module nodes from ``graph``
77        :param graph: graph of module nodes to load
78        :param status: status dictionary for keeping track of progress
79        :param perform_checks: whether module descriptors should be checked for validity (prints warnings
80                               for same cases, and even raise osv_except if certificate is invalid)
81        :param skip_modules: optional list of module names (packages) which have previously been loaded and can be skipped
82        :return: list of modules that were installed or updated
83     """
84     logger = logging.getLogger('init.load')
85     def process_sql_file(cr, fp):
86         queries = fp.read().split(';')
87         for query in queries:
88             new_query = ' '.join(query.split())
89             if new_query:
90                 cr.execute(new_query)
91
92     def load_init_xml(cr, module_name, idref, mode):
93         _load_data(cr, module_name, idref, mode, 'init_xml')
94
95     def load_update_xml(cr, module_name, idref, mode):
96         _load_data(cr, module_name, idref, mode, 'update_xml')
97
98     def load_demo_xml(cr, module_name, idref, mode):
99         _load_data(cr, module_name, idref, mode, 'demo_xml')
100
101     def load_data(cr, module_name, idref, mode):
102         _load_data(cr, module_name, idref, mode, 'data')
103
104     def load_demo(cr, module_name, idref, mode):
105         _load_data(cr, module_name, idref, mode, 'demo')
106
107     def load_test(cr, module_name, idref, mode):
108         cr.commit()
109         if not tools.config.options['test_disable']:
110             try:
111                 _load_data(cr, module_name, idref, mode, 'test')
112             except Exception, e:
113                 logging.getLogger('init.test').exception(
114                     'Tests failed to execute in module %s', module_name)
115             finally:
116                 if tools.config.options['test_commit']:
117                     cr.commit()
118                 else:
119                     cr.rollback()
120
121     def _load_data(cr, module_name, idref, mode, kind):
122         """
123
124         kind: data, demo, test, init_xml, update_xml, demo_xml.
125
126         noupdate is False, unless it is demo data or it is csv data in
127         init mode.
128
129         """
130         for filename in package.data[kind]:
131             logger.info("module %s: loading %s", module_name, filename)
132             _, ext = os.path.splitext(filename)
133             pathname = os.path.join(module_name, filename)
134             fp = tools.file_open(pathname)
135             noupdate = False
136             if kind in ('demo', 'demo_xml'):
137                 noupdate = True
138             try:
139                 if ext == '.csv':
140                     if kind in ('init', 'init_xml'):
141                         noupdate = True
142                     tools.convert_csv_import(cr, module_name, pathname, fp.read(), idref, mode, noupdate)
143                 elif ext == '.sql':
144                     process_sql_file(cr, fp)
145                 elif ext == '.yml':
146                     tools.convert_yaml_import(cr, module_name, fp, idref, mode, noupdate)
147                 else:
148                     tools.convert_xml_import(cr, module_name, fp, idref, mode, noupdate, report)
149             finally:
150                 fp.close()
151
152     if status is None:
153         status = {}
154
155     processed_modules = []
156     loaded_modules = []
157     pool = pooler.get_pool(cr.dbname)
158     migrations = openerp.modules.migration.MigrationManager(cr, graph)
159     logger.debug('loading %d packages...', len(graph))
160
161     # register, instantiate and initialize models for each modules
162     for index, package in enumerate(graph):
163         module_name = package.name
164         module_id = package.id
165
166         if skip_modules and module_name in skip_modules:
167             continue
168
169         logger.info('module %s: loading objects', package.name)
170         migrations.migrate_module(package, 'pre')
171         register_module_classes(package.name)
172         models = pool.instanciate(package.name, cr)
173         loaded_modules.append(package.name)
174         if hasattr(package, 'init') or hasattr(package, 'update') or package.state in ('to install', 'to upgrade'):
175             init_module_models(cr, package.name, models)
176
177         status['progress'] = float(index) / len(graph)
178
179         # Can't put this line out of the loop: ir.module.module will be
180         # registered by init_module_models() above.
181         modobj = pool.get('ir.module.module')
182
183         if perform_checks:
184             modobj.check(cr, 1, [module_id])
185
186         idref = {}
187
188         mode = 'update'
189         if hasattr(package, 'init') or package.state == 'to install':
190             mode = 'init'
191
192         if hasattr(package, 'init') or hasattr(package, 'update') or package.state in ('to install', 'to upgrade'):
193             if package.state=='to upgrade':
194                 # upgrading the module information
195                 modobj.write(cr, 1, [module_id], modobj.get_values_from_terp(package.data))
196             load_init_xml(cr, module_name, idref, mode)
197             load_update_xml(cr, module_name, idref, mode)
198             load_data(cr, module_name, idref, mode)
199             if hasattr(package, 'demo') or (package.dbdemo and package.state != 'installed'):
200                 status['progress'] = (index + 0.75) / len(graph)
201                 load_demo_xml(cr, module_name, idref, mode)
202                 load_demo(cr, module_name, idref, mode)
203                 cr.execute('update ir_module_module set demo=%s where id=%s', (True, module_id))
204
205                 # launch tests only in demo mode, as most tests will depend
206                 # on demo data. Other tests can be added into the regular
207                 # 'data' section, but should probably not alter the data,
208                 # as there is no rollback.
209                 load_test(cr, module_name, idref, mode)
210
211             processed_modules.append(package.name)
212
213             migrations.migrate_module(package, 'post')
214
215             ver = release.major_version + '.' + package.data['version']
216             # Set new modules and dependencies
217             modobj.write(cr, 1, [module_id], {'state': 'installed', 'latest_version': ver})
218             # Update translations for all installed languages
219             modobj.update_translations(cr, 1, [module_id], None)
220
221             package.state = 'installed'
222             for kind in ('init', 'demo', 'update'):
223                 if hasattr(package, kind):
224                     delattr(package, kind)
225
226         cr.commit()
227
228     cr.commit()
229
230     return loaded_modules, processed_modules
231
232 def _check_module_names(cr, module_names):
233     mod_names = set(module_names)
234     if 'base' in mod_names:
235         # ignore dummy 'all' module
236         if 'all' in mod_names:
237             mod_names.remove('all')
238     if mod_names:
239         cr.execute("SELECT count(id) AS count FROM ir_module_module WHERE name in %s", (tuple(mod_names),))
240         if cr.dictfetchone()['count'] != len(mod_names):
241             # find out what module name(s) are incorrect:
242             cr.execute("SELECT name FROM ir_module_module")
243             incorrect_names = mod_names.difference([x['name'] for x in cr.dictfetchall()])
244             logging.getLogger('init').warning('invalid module names, ignored: %s', ", ".join(incorrect_names))
245
246 def load_marked_modules(cr, graph, states, force, progressdict, report, loaded_modules):
247     """Loads modules marked with ``states``, adding them to ``graph`` and
248        ``loaded_modules`` and returns a list of installed/upgraded modules."""
249     processed_modules = []
250     while True:
251         cr.execute("SELECT name from ir_module_module WHERE state IN %s" ,(tuple(states),))
252         module_list = [name for (name,) in cr.fetchall() if name not in graph]
253         new_modules_in_graph = graph.add_modules(cr, module_list, force)
254         logger.notifyChannel('init', netsvc.LOG_DEBUG, 'Updating graph with %d more modules' % (len(module_list)))
255         loaded, processed = load_module_graph(cr, graph, progressdict, report=report, skip_modules=loaded_modules)
256         processed_modules.extend(processed)
257         loaded_modules.extend(loaded)
258         if not processed: break
259     return processed_modules
260
261
262 def load_modules(db, force_demo=False, status=None, update_module=False):
263     # TODO status['progress'] reporting is broken: used twice (and reset each
264     # time to zero) in load_module_graph, not fine-grained enough.
265     # It should be a method exposed by the pool.
266     initialize_sys_path()
267
268     open_openerp_namespace()
269
270     force = []
271     if force_demo:
272         force.append('demo')
273
274     cr = db.cursor()
275     try:
276         if not openerp.modules.db.is_initialized(cr):
277             logger.notifyChannel("init", netsvc.LOG_INFO, "init db")
278             openerp.modules.db.initialize(cr)
279             tools.config["init"]["all"] = 1
280             tools.config['update']['all'] = 1
281             if not tools.config['without_demo']:
282                 tools.config["demo"]['all'] = 1
283
284         # This is a brand new pool, just created in pooler.get_db_and_pool()
285         pool = pooler.get_pool(cr.dbname)
286
287         processed_modules = [] # for cleanup step after install
288         loaded_modules = [] # to avoid double loading
289         report = tools.assertion_report()
290         if 'base' in tools.config['update'] or 'all' in tools.config['update']:
291             cr.execute("update ir_module_module set state=%s where name=%s and state=%s", ('to upgrade', 'base', 'installed'))
292
293         # STEP 1: LOAD BASE (must be done before module dependencies can be computed for later steps) 
294         graph = openerp.modules.graph.Graph()
295         graph.add_module(cr, 'base', force)
296         if not graph:
297             logger.notifyChannel('init', netsvc.LOG_CRITICAL, 'module base cannot be loaded! (hint: verify addons-path)')
298             raise osv.osv.except_osv(_('Could not load base module'), _('module base cannot be loaded! (hint: verify addons-path)'))
299         loaded, processed = load_module_graph(cr, graph, status, perform_checks=(not update_module), report=report)
300         processed_modules.extend(processed)
301
302         if tools.config['load_language']:
303             for lang in tools.config['load_language'].split(','):
304                 tools.load_language(cr, lang)
305
306         # STEP 2: Mark other modules to be loaded/updated
307         if update_module:
308             modobj = pool.get('ir.module.module')
309             if ('base' in tools.config['init']) or ('base' in tools.config['update']):
310                 logger.notifyChannel('init', netsvc.LOG_INFO, 'updating modules list')
311                 modobj.update_list(cr, 1)
312
313             _check_module_names(cr, itertools.chain(tools.config['init'].keys(), tools.config['update'].keys()))
314
315             mods = [k for k in tools.config['init'] if tools.config['init'][k]]
316             if mods:
317                 ids = modobj.search(cr, 1, ['&', ('state', '=', 'uninstalled'), ('name', 'in', mods)])
318                 if ids:
319                     modobj.button_install(cr, 1, ids)
320
321             mods = [k for k in tools.config['update'] if tools.config['update'][k]]
322             if mods:
323                 ids = modobj.search(cr, 1, ['&', ('state', '=', 'installed'), ('name', 'in', mods)])
324                 if ids:
325                     modobj.button_upgrade(cr, 1, ids)
326
327             cr.execute("update ir_module_module set state=%s where name=%s", ('installed', 'base'))
328
329
330         # STEP 3: Load marked modules (skipping base which was done in STEP 1)
331         # IMPORTANT: this is done in two parts, first loading all installed or
332         #            partially installed modules (i.e. installed/to upgrade), to
333         #            offer a consistent system to the second part: installing
334         #            newly selected modules.
335         states_to_load = ['installed', 'to upgrade']
336         processed = load_marked_modules(cr, graph, states_to_load, force, status, report, loaded_modules)
337         processed_modules.extend(processed)
338         if update_module:
339             states_to_load = ['to install']
340             processed = load_marked_modules(cr, graph, states_to_load, force, status, report, loaded_modules)
341             processed_modules.extend(processed)
342
343         # load custom models
344         cr.execute('select model from ir_model where state=%s', ('manual',))
345         for model in cr.dictfetchall():
346             pool.get('ir.model').instanciate(cr, 1, model['model'], {})
347
348         # STEP 4: Finish and cleanup
349         if processed_modules:
350             cr.execute("""select model,name from ir_model where id NOT IN (select distinct model_id from ir_model_access)""")
351             for (model, name) in cr.fetchall():
352                 model_obj = pool.get(model)
353                 if model_obj and not isinstance(model_obj, osv.osv.osv_memory):
354                     logger.notifyChannel('init', netsvc.LOG_WARNING, 'object %s (%s) has no access rules!' % (model, name))
355
356             # Temporary warning while we remove access rights on osv_memory objects, as they have
357             # been replaced by owner-only access rights
358             cr.execute("""select distinct mod.model, mod.name from ir_model_access acc, ir_model mod where acc.model_id = mod.id""")
359             for (model, name) in cr.fetchall():
360                 model_obj = pool.get(model)
361                 if isinstance(model_obj, osv.osv.osv_memory):
362                     logger.notifyChannel('init', netsvc.LOG_WARNING, 'In-memory object %s (%s) should not have explicit access rules!' % (model, name))
363
364             cr.execute("SELECT model from ir_model")
365             for (model,) in cr.fetchall():
366                 obj = pool.get(model)
367                 if obj:
368                     obj._check_removed_columns(cr, log=True)
369                 else:
370                     logger.notifyChannel('init', netsvc.LOG_WARNING, "Model %s is referenced but not present in the orm pool!" % model)
371
372             # Cleanup orphan records
373             pool.get('ir.model.data')._process_end(cr, 1, processed_modules)
374
375         if report.get_report():
376             logger.notifyChannel('init', netsvc.LOG_INFO, report)
377
378         for kind in ('init', 'demo', 'update'):
379             tools.config[kind] = {}
380
381         cr.commit()
382         if update_module:
383             # Remove records referenced from ir_model_data for modules to be
384             # removed (and removed the references from ir_model_data).
385             cr.execute("select id,name from ir_module_module where state=%s", ('to remove',))
386             for mod_id, mod_name in cr.fetchall():
387                 cr.execute('select model,res_id from ir_model_data where noupdate=%s and module=%s order by id desc', (False, mod_name,))
388                 for rmod, rid in cr.fetchall():
389                     uid = 1
390                     rmod_module= pool.get(rmod)
391                     if rmod_module:
392                         # TODO group by module so that we can delete multiple ids in a call
393                         rmod_module.unlink(cr, uid, [rid])
394                     else:
395                         logger.notifyChannel('init', netsvc.LOG_ERROR, 'Could not locate %s to remove res=%d' % (rmod,rid))
396                 cr.execute('delete from ir_model_data where noupdate=%s and module=%s', (False, mod_name,))
397                 cr.commit()
398
399             # Remove menu items that are not referenced by any of other
400             # (child) menu item, ir_values, or ir_model_data.
401             # This code could be a method of ir_ui_menu.
402             # TODO: remove menu without actions of children
403             while True:
404                 cr.execute('''delete from
405                         ir_ui_menu
406                     where
407                         (id not IN (select parent_id from ir_ui_menu where parent_id is not null))
408                     and
409                         (id not IN (select res_id from ir_values where model='ir.ui.menu'))
410                     and
411                         (id not IN (select res_id from ir_model_data where model='ir.ui.menu'))''')
412                 cr.commit()
413                 if not cr.rowcount:
414                     break
415                 else:
416                     logger.notifyChannel('init', netsvc.LOG_INFO, 'removed %d unused menus' % (cr.rowcount,))
417
418             # Pretend that modules to be removed are actually uninstalled.
419             cr.execute("update ir_module_module set state=%s where state=%s", ('uninstalled', 'to remove',))
420             cr.commit()
421     finally:
422         cr.close()
423
424
425 # vim:expandtab:smartindent:tabstop=4:softtabstop=4:shiftwidth=4: