data.py 19.6 KB
Newer Older
Markus Scheidgen's avatar
Markus Scheidgen committed
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
# Copyright 2018 Markus Scheidgen
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#   http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an"AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

"""
This module comprises a set of persistent document classes that hold all user related
data. These are information about users, their uploads and datasets, the associated
calculations, and files


.. autoclass:: Calc
    :members:
.. autoclass:: Upload
    :members:
"""

27
from typing import List, Any, ContextManager
Markus Scheidgen's avatar
Markus Scheidgen committed
28
from datetime import datetime
29
from elasticsearch.exceptions import NotFoundError
Markus Scheidgen's avatar
Markus Scheidgen committed
30
from mongoengine import StringField, BooleanField, DateTimeField, DictField, IntField
Markus Scheidgen's avatar
Markus Scheidgen committed
31
import logging
32
import base64
Markus Scheidgen's avatar
Markus Scheidgen committed
33
import time
34
from structlog import wrap_logger
Markus Scheidgen's avatar
Markus Scheidgen committed
35

36
from nomad import config, utils
Markus Scheidgen's avatar
Markus Scheidgen committed
37
from nomad.files import UploadFile, ArchiveFile, ArchiveLogFile, File
Markus Scheidgen's avatar
Markus Scheidgen committed
38
from nomad.repo import RepoCalc
Markus Scheidgen's avatar
Markus Scheidgen committed
39
from nomad.user import User
40
from nomad.processing.base import Proc, Chord, process, task, PENDING, SUCCESS, FAILURE, RUNNING
Markus Scheidgen's avatar
Markus Scheidgen committed
41
from nomad.parsing import parsers, parser_dict
Markus Scheidgen's avatar
Markus Scheidgen committed
42
from nomad.normalizing import normalizers
Markus Scheidgen's avatar
Markus Scheidgen committed
43
from nomad.utils import lnr
Markus Scheidgen's avatar
Markus Scheidgen committed
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73


class NotAllowedDuringProcessing(Exception): pass


class Calc(Proc):
    """
    Instances of this class represent calculations. This class manages the elastic
    search index entry, files, and archive for the respective calculation.

    It also contains the calculations processing and its state.

    The attribute list, does not include the various repository properties generated
    while parsing, including ``program_name``, ``program_version``, etc.

    Attributes:
        archive_id: the hash based archive id of the calc
        parser: the name of the parser used to process this calc
        upload_id: the id of the upload used to create this calculation
        mainfile: the mainfile (including path in upload) that was used to create this calc
        mainfile_tmp_path: path to the mainfile extracted for processing
    """
    archive_id = StringField(primary_key=True)
    upload_id = StringField()
    mainfile = StringField()
    parser = StringField()
    mainfile_tmp_path = StringField()

    meta: Any = {
        'indices': [
74
            'upload_id', 'mainfile', 'code', 'parser', 'status'
Markus Scheidgen's avatar
Markus Scheidgen committed
75
76
77
78
79
80
81
        ]
    }

    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self._parser_backend = None
        self._upload = None
82
        self._calc_proc_logwriter = None
Markus Scheidgen's avatar
Markus Scheidgen committed
83
        self._calc_proc_logfile = None
84
        self._calc_proc_logwriter_ctx: ContextManager = None
Markus Scheidgen's avatar
Markus Scheidgen committed
85
86
87
88
89

    @classmethod
    def get(cls, id):
        return cls.get_by_id(id, 'archive_id')

Markus Scheidgen's avatar
Markus Scheidgen committed
90
91
92
93
    @property
    def mainfile_file(self) -> File:
        return File(self.mainfile_tmp_path)

94
95
96
97
98
99
    @property
    def upload(self) -> 'Upload':
        if not self._upload:
            self._upload = Upload.get(self.upload_id)
        return self._upload

Markus Scheidgen's avatar
Markus Scheidgen committed
100
101
102
103
    def delete(self):
        """
        Delete this calculation and all associated data. This includes all files,
        the archive, and this search index entry.
104
        TODO is this needed? Or do we always delete hole uploads in bulk.
Markus Scheidgen's avatar
Markus Scheidgen committed
105
106
107
        """
        # delete the archive
        if self.archive_id is not None:
108
            ArchiveFile(self.archive_id).delete()
Markus Scheidgen's avatar
Markus Scheidgen committed
109
110

        # delete the search index entry
111
112
113
114
115
116
        try:
            elastic_entry = RepoCalc.get(self.archive_id)
            if elastic_entry is not None:
                elastic_entry.delete()
        except NotFoundError:
            pass
Markus Scheidgen's avatar
Markus Scheidgen committed
117
118
119
120
121
122
123
124
125

        # delete this mongo document
        super().delete()

    def get_logger(self, **kwargs):
        upload_hash, calc_hash = self.archive_id.split('/')
        logger = super().get_logger()
        logger = logger.bind(
            upload_id=self.upload_id, mainfile=self.mainfile,
126
            upload_hash=upload_hash, calc_hash=calc_hash,
Markus Scheidgen's avatar
Markus Scheidgen committed
127
            archive_id=self.archive_id, **kwargs)
128

Markus Scheidgen's avatar
Markus Scheidgen committed
129
130
        return logger

131
132
133
134
135
136
137
138
    def get_calc_logger(self, **kwargs):
        """
        Returns a wrapped logger that additionally saves all entries to the calculation
        processing log in the archive.
        """
        logger = self.get_logger(**kwargs)

        if self._calc_proc_logwriter is None:
Markus Scheidgen's avatar
Markus Scheidgen committed
139
            self._calc_proc_logfile = ArchiveLogFile(self.archive_id)
140
141
            self._calc_proc_logwriter_ctx = self._calc_proc_logfile.open('wt')
            self._calc_proc_logwriter = self._calc_proc_logwriter_ctx.__enter__()  # pylint: disable=E1101
142

143
        def save_to_calc_log(logger, method_name, event_dict):
144
145
146
147
148
149
150
151
152
153
154
            program = event_dict.get('normalizer', 'parser')
            event = event_dict.get('event', '')
            entry = '[%s] %s: %s' % (method_name, program, event)
            if len(entry) > 120:
                self._calc_proc_logwriter.write(entry[:120])
                self._calc_proc_logwriter.write('...')
            else:
                self._calc_proc_logwriter.write(entry)
            self._calc_proc_logwriter.write('\n')
            return event_dict

155
        return wrap_logger(logger, processors=[save_to_calc_log])
156

Markus Scheidgen's avatar
Markus Scheidgen committed
157
158
159
160
161
162
163
164
165
166
167
168
169
170
    @property
    def json_dict(self):
        """ A json serializable dictionary representation. """
        data = {
            'archive_id': self.archive_id,
            'mainfile': self.mainfile,
            'upload_id': self.upload_id,
            'parser': self.parser
        }
        data.update(super().json_dict)
        return {key: value for key, value in data.items() if value is not None}

    @process
    def process(self):
171
        logger = self.get_logger()
172
        if self.upload is None:
173
            logger.error('calculation upload does not exist')
Markus Scheidgen's avatar
Markus Scheidgen committed
174
175
176
177
178
179

        try:
            self.parsing()
            self.normalizing()
            self.archiving()
        finally:
Markus Scheidgen's avatar
Markus Scheidgen committed
180
            # close loghandler that was not closed due to failures
181
            try:
182
183
184
                if self._calc_proc_logwriter is not None:
                    self._calc_proc_logwriter.close()
                    self._calc_proc_logwriter = None
185
186
187
188
            except Exception as e:
                logger.error('could not close calculation proc log', exc_info=e)

            # inform parent proc about completion
189
            self.upload.completed_child()
Markus Scheidgen's avatar
Markus Scheidgen committed
190
191
192

    @task
    def parsing(self):
193
194
        context = dict(parser=self.parser, step=self.parser)
        logger = self.get_calc_logger(**context)
195
        parser = parser_dict[self.parser]
Markus Scheidgen's avatar
Markus Scheidgen committed
196

197
        with utils.timer(logger, 'parser executed', input_size=self.mainfile_file.size):
198
            self._parser_backend = parser.run(self.mainfile_tmp_path, logger=logger)
Markus Scheidgen's avatar
Markus Scheidgen committed
199

Markus Scheidgen's avatar
Markus Scheidgen committed
200
        if self._parser_backend.status[0] != 'ParseSuccess':
201
            logger.error(self._parser_backend.status[1])
Markus Scheidgen's avatar
Markus Scheidgen committed
202
            error = self._parser_backend.status[1]
203
            self.fail(error, level=logging.DEBUG, **context)
Markus Scheidgen's avatar
Markus Scheidgen committed
204
205
206
207
208

    @task
    def normalizing(self):
        for normalizer in normalizers:
            normalizer_name = normalizer.__name__
209
210
            context = dict(normalizer=normalizer_name, step=normalizer_name)
            logger = self.get_calc_logger(**context)
Markus Scheidgen's avatar
Markus Scheidgen committed
211
212

            with utils.timer(
213
                    logger, 'normalizer executed', input_size=self.mainfile_file.size):
214
                normalizer(self._parser_backend).normalize(logger=logger)
Markus Scheidgen's avatar
Markus Scheidgen committed
215

Markus Scheidgen's avatar
Markus Scheidgen committed
216
            if self._parser_backend.status[0] != 'ParseSuccess':
217
                logger.error(self._parser_backend.status[1])
Markus Scheidgen's avatar
Markus Scheidgen committed
218
                error = self._parser_backend.status[1]
219
                self.fail(error, level=logging.WARNING, **context)
Markus Scheidgen's avatar
Markus Scheidgen committed
220
                return
221
            logger.debug(
Markus Scheidgen's avatar
Markus Scheidgen committed
222
223
224
225
                'completed normalizer successfully', normalizer=normalizer_name)

    @task
    def archiving(self):
226
227
228
229
230
        logger = self.get_logger()

        upload_hash, calc_hash = self.archive_id.split('/')
        additional = dict(
            mainfile=self.mainfile,
231
            upload_time=self.upload.upload_time,
232
233
            staging=True,
            restricted=False,
234
235
            user_id=self.upload.user_id,
            aux_files=list(self.upload.upload_file.get_siblings(self.mainfile)))
236
237

        with utils.timer(logger, 'indexed', step='index'):
238
239
240
241
242
243
244
245
            # persist to elastic search
            RepoCalc.create_from_backend(
                self._parser_backend,
                additional=additional,
                upload_hash=upload_hash,
                calc_hash=calc_hash,
                upload_id=self.upload_id)

Markus Scheidgen's avatar
Markus Scheidgen committed
246
247
248
249
        with utils.timer(
                logger, 'archived', step='archive',
                input_size=self.mainfile_file.size) as log_data:

250
            # persist the archive
Markus Scheidgen's avatar
Markus Scheidgen committed
251
252
            archive_file = ArchiveFile(self.archive_id)
            with archive_file.write_archive_json() as out:
253
254
                self._parser_backend.write_json(out, pretty=True)

Markus Scheidgen's avatar
Markus Scheidgen committed
255
256
257
258
259
260
261
            log_data.update(archive_size=archive_file.size)

        # close loghandler
        if self._calc_proc_logwriter is not None:
            with utils.timer(
                    logger, 'archived log', step='archive_log',
                    input_size=self.mainfile_file.size) as log_data:
262
                self._calc_proc_logwriter_ctx.__exit__(None, None, None)  # pylint: disable=E1101
263
                self._calc_proc_logwriter = None
Markus Scheidgen's avatar
Markus Scheidgen committed
264

Markus Scheidgen's avatar
Markus Scheidgen committed
265
266
                log_data.update(log_size=self._calc_proc_logfile.size)

Markus Scheidgen's avatar
Markus Scheidgen committed
267

268
class Upload(Chord):
Markus Scheidgen's avatar
Markus Scheidgen committed
269
270
271
272
273
274
    """
    Represents uploads in the databases. Provides persistence access to the files storage,
    and processing state.

    Attributes:
        name: optional user provided upload name
275
        local_path: optional local path, e.g. for files that are already somewhere on the server
Markus Scheidgen's avatar
Markus Scheidgen committed
276
277
278
279
280
281
        additional_metadata: optional user provided additional meta data
        upload_id: the upload id generated by the database
        in_staging: true if the upload is still in staging and can be edited by the uploader
        is_private: true if the upload and its derivitaves are only visible to the uploader
        upload_time: the timestamp when the system realised the upload
        upload_hash: the hash of the uploaded file
282
        user_id: the id of the user that created this upload
Markus Scheidgen's avatar
Markus Scheidgen committed
283
284
285
286
287
288
    """
    id_field = 'upload_id'

    upload_id = StringField(primary_key=True)

    name = StringField(default=None)
289
    local_path = StringField(default=None)
Markus Scheidgen's avatar
Markus Scheidgen committed
290
291
292
293
294
295
296
297
    additional_metadata = DictField(default=None)

    in_staging = BooleanField(default=True)
    is_private = BooleanField(default=False)

    upload_time = DateTimeField()
    upload_hash = StringField(default=None)

298
    user_id = StringField(required=True)
299
300
    upload_url = StringField(default=None)
    upload_command = StringField(default=None)
Markus Scheidgen's avatar
Markus Scheidgen committed
301

302
303
    _initiated_parsers = IntField(default=-1)

Markus Scheidgen's avatar
Markus Scheidgen committed
304
305
    meta: Any = {
        'indexes': [
306
            'upload_hash', 'user_id', 'status'
Markus Scheidgen's avatar
Markus Scheidgen committed
307
308
309
310
311
        ]
    }

    def __init__(self, **kwargs):
        super().__init__(**kwargs)
312
        self._upload_file = None
Markus Scheidgen's avatar
Markus Scheidgen committed
313
314
315
316
317
318
319
320

    @classmethod
    def get(cls, id):
        return cls.get_by_id(id, 'upload_id')

    @classmethod
    def user_uploads(cls, user: User) -> List['Upload']:
        """ Returns all uploads for the given user. Currently returns all uploads. """
Markus Scheidgen's avatar
Markus Scheidgen committed
321
        return cls.objects(user_id=user.email, in_staging=True)
Markus Scheidgen's avatar
Markus Scheidgen committed
322
323
324
325
326
327
328
329
330
331
332
333
334
335

    def get_logger(self, **kwargs):
        logger = super().get_logger()
        logger = logger.bind(upload_id=self.upload_id, **kwargs)
        return logger

    def delete(self):
        logger = self.get_logger(task='delete')

        if not (self.completed or self.is_stale or self.current_task == 'uploading'):
            raise NotAllowedDuringProcessing()

        with lnr(logger, 'delete upload file'):
            try:
336
                UploadFile(self.upload_id, local_path=self.local_path).delete()
Markus Scheidgen's avatar
Markus Scheidgen committed
337
338
339
340
341
342
343
344
345
            except KeyError:
                if self.current_task == 'uploading':
                    logger.debug(
                        'Upload exist, but file does not exist. '
                        'It was probably aborted and deleted.')
                else:
                    logger.debug('Upload exist, but uploaded file does not exist.')

        with lnr(logger, 'deleting calcs'):
346
            # delete archive files
347
            ArchiveFile.delete_archives(upload_hash=self.upload_hash)
348
349

            # delete repo entries
Markus Scheidgen's avatar
Markus Scheidgen committed
350
            RepoCalc.delete_upload(upload_id=self.upload_id)
351
352
353

            # delete calc processings
            Calc.objects(upload_id=self.upload_id).delete()
Markus Scheidgen's avatar
Markus Scheidgen committed
354
355
356
357

        with lnr(logger, 'deleting upload'):
            super().delete()

358
359
    @classmethod
    def _external_objects_url(cls, url):
360
        """ Replaces the given internal object storage url with an URL that allows
361
362
            external access.
        """
363
        return 'http://%s:%s%s%s' % (config.services.api_host, config.services.api_port, config.services.api_base_path, url)
364

Markus Scheidgen's avatar
Markus Scheidgen committed
365
366
367
368
369
370
    @classmethod
    def create(cls, **kwargs) -> 'Upload':
        """
        Creates a new upload for the given user, a user given name is optional.
        It will populate the record with a signed url and pending :class:`UploadProc`.
        The upload will be already saved to the database.
371
372
373

        Arguments:
            user (User): The user that created the upload.
Markus Scheidgen's avatar
Markus Scheidgen committed
374
        """
375
376
377
378
379
        user: User = kwargs['user']
        del(kwargs['user'])
        if 'upload_id' not in kwargs:
            kwargs.update(upload_id=utils.create_uuid())
        kwargs.update(user_id=user.email)
Markus Scheidgen's avatar
Markus Scheidgen committed
380
        self = super().create(**kwargs)
381
382
383
384

        basic_auth_token = base64.b64encode(b'%s:' % user.generate_auth_token()).decode('utf-8')

        self.upload_url = cls._external_objects_url('/uploads/%s/file' % self.upload_id)
Markus Scheidgen's avatar
Markus Scheidgen committed
385
        self.upload_command = 'curl -H "Authorization: Basic %s" "%s" --upload-file local_file' % (
386
387
            basic_auth_token, self.upload_url)

Markus Scheidgen's avatar
Markus Scheidgen committed
388
        self._continue_with('uploading')
389

Markus Scheidgen's avatar
Markus Scheidgen committed
390
391
392
393
394
395
396
397
398
        return self

    @property
    def is_stale(self) -> bool:
        if self.current_task == 'uploading' and self.upload_time is None:
            return (datetime.now() - self.create_time).days > 1
        else:
            return False

Markus Scheidgen's avatar
Markus Scheidgen committed
399
    def unstage(self):
400
        self.get_logger().info('unstage')
Markus Scheidgen's avatar
Markus Scheidgen committed
401
        self.in_staging = False
402
        RepoCalc.unstage(upload_id=self.upload_id)
Markus Scheidgen's avatar
Markus Scheidgen committed
403
404
        self.save()

Markus Scheidgen's avatar
Markus Scheidgen committed
405
406
407
408
409
    @property
    def json_dict(self) -> dict:
        """ A json serializable dictionary representation. """
        data = {
            'name': self.name,
410
            'local_path': self.local_path,
Markus Scheidgen's avatar
Markus Scheidgen committed
411
412
            'additional_metadata': self.additional_metadata,
            'upload_id': self.upload_id,
413
            'upload_url': self.upload_url,
414
            'upload_command': self.upload_command,
Markus Scheidgen's avatar
Markus Scheidgen committed
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
            'upload_time': self.upload_time.isoformat() if self.upload_time is not None else None,
            'is_stale': self.is_stale,
        }
        data.update(super().json_dict)
        return {key: value for key, value in data.items() if value is not None}

    @process
    def process(self):
        self.extracting()
        self.parse_all()

    @task
    def uploading(self):
        pass

430
431
432
433
434
435
436
    @property
    def upload_file(self):
        """ The :class:`UploadFile` instance that represents the uploaded file of this upload. """
        if not self._upload_file:
            self._upload_file = UploadFile(self.upload_id, local_path=self.local_path)
        return self._upload_file

Markus Scheidgen's avatar
Markus Scheidgen committed
437
438
439
440
    @task
    def extracting(self):
        logger = self.get_logger()
        try:
Markus Scheidgen's avatar
Markus Scheidgen committed
441
442
            with utils.timer(
                    logger, 'upload extracted', step='extracting',
443
444
                    upload_size=self.upload_file.size):
                self.upload_file.extract()
Markus Scheidgen's avatar
Markus Scheidgen committed
445
446
447
448
449
        except KeyError as e:
            self.fail('process request for non existing upload', level=logging.INFO)
            return

        try:
450
            self.upload_hash = self.upload_file.hash()
451
        except Exception as e:
Markus Scheidgen's avatar
Markus Scheidgen committed
452
453
454
            self.fail('could not create upload hash', e)
            return

Markus Scheidgen's avatar
Markus Scheidgen committed
455
        if RepoCalc.upload_exists(self.upload_hash):
Markus Scheidgen's avatar
Markus Scheidgen committed
456
457
458
459
460
            self.fail('The same file was already uploaded and processed.', level=logging.INFO)
            return

    @task
    def parse_all(self):
461
462
        logger = self.get_logger()

Markus Scheidgen's avatar
Markus Scheidgen committed
463
        # TODO: deal with multiple possible parser specs
Markus Scheidgen's avatar
Markus Scheidgen committed
464
465
        with utils.timer(
                logger, 'upload extracted', step='matching',
466
467
                upload_size=self.upload_file.size,
                upload_filecount=len(self.upload_file.filelist)):
468
            total_calcs = 0
469
            for filename in self.upload_file.filelist:
470
471
                for parser in parsers:
                    try:
472
                        potential_mainfile = self.upload_file.get_file(filename)
473
474
475
476
477
478
479
480
481
482
483
                        with potential_mainfile.open() as mainfile_f:
                            if parser.is_mainfile(filename, lambda fn: mainfile_f):
                                mainfile_path = potential_mainfile.os_path
                                calc = Calc.create(
                                    archive_id='%s/%s' % (self.upload_hash, utils.hash(filename)),
                                    mainfile=filename, parser=parser.name,
                                    mainfile_tmp_path=mainfile_path,
                                    upload_id=self.upload_id)

                                calc.process()
                                total_calcs += 1
484
                    except Exception as e:
Markus Scheidgen's avatar
Markus Scheidgen committed
485
                        self.error(
486
487
                            'exception while matching pot. mainfile',
                            mainfile=filename, exc_info=e)
Markus Scheidgen's avatar
Markus Scheidgen committed
488

489
490
491
492
493
        # have to save the total_calcs information for chord management
        self.spwaned_childred(total_calcs)

    def join(self):
        self.cleanup()
Markus Scheidgen's avatar
Markus Scheidgen committed
494
495
496
497

    @task
    def cleanup(self):
        try:
Markus Scheidgen's avatar
Markus Scheidgen committed
498
499
500
501
502
            upload = UploadFile(self.upload_id, local_path=self.local_path)
            with utils.timer(
                    self.get_logger(), 'processing cleaned up', step='cleaning',
                    upload_size=upload.size):
                upload.remove_extract()
Markus Scheidgen's avatar
Markus Scheidgen committed
503
        except KeyError as e:
Markus Scheidgen's avatar
Markus Scheidgen committed
504
            self.fail('Upload does not exist', exc_info=e)
Markus Scheidgen's avatar
Markus Scheidgen committed
505
506
507
508
509
            return

        self.get_logger().debug('closed upload')

    @property
510
511
512
513
514
515
516
517
518
519
520
    def processed_calcs(self):
        return Calc.objects(upload_id=self.upload_id, status__in=[SUCCESS, FAILURE]).count()

    @property
    def total_calcs(self):
        return Calc.objects(upload_id=self.upload_id).count()

    @property
    def failed_calcs(self):
        return Calc.objects(upload_id=self.upload_id, status=FAILURE).count()

521
522
523
524
    @property
    def pending_calcs(self):
        return Calc.objects(upload_id=self.upload_id, status=PENDING).count()

525
526
    def all_calcs(self, start, end, order_by='mainfile'):
        return Calc.objects(upload_id=self.upload_id)[start:end].order_by(order_by)
527

Markus Scheidgen's avatar
Markus Scheidgen committed
528
    @staticmethod
529
530
531
532
533
    def repair_all():
        """
        Utitlity function that will look for suspiciously looking conditions in
        all uncompleted downloads. It ain't a perfect world.
        """
534
535
536
        # TODO this was added as a quick fix to #37.
        # Even though it might be strictly necessary, there should be a tested backup
        # solution for it Chords to not work properly due to failed to fail processings
537
538
539
540
541
542
543
544
545
546
        uploads = Upload.objects(status__in=[PENDING, RUNNING])
        for upload in uploads:
            completed = upload.processed_calcs
            total = upload.total
            pending = upload.pending_calcs

            if completed + pending == total:
                time.sleep(2)
                if pending == upload.pending_calcs:
                    Calc.objects(upload_id=upload.upload_id, status=PENDING).delete()