invenio-demosite.log

2015-04-02 15:13:53 --> Task #1 submitted.
2015-04-02 15:13:57 --> Task #1 started.
2015-04-02 15:13:57 --> Input file '/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/testsuite/data/demo_record_marc_data.xml', input mode 'insert'.
2015-04-02 15:14:00 --> Record 1 DONE
2015-04-02 15:14:00 --> Record 2 DONE
2015-04-02 15:14:00 --> Record 3 DONE
2015-04-02 15:14:00 --> Record 4 DONE
2015-04-02 15:14:00 --> Record 5 DONE
2015-04-02 15:14:01 --> Record 6 DONE
2015-04-02 15:14:01 --> Record 7 DONE
2015-04-02 15:14:01 --> Record 8 DONE
2015-04-02 15:14:01 --> Record 9 DONE
2015-04-02 15:14:01 --> Record 10 DONE
2015-04-02 15:14:02 --> Record 11 DONE
2015-04-02 15:14:03 --> Record 12 DONE
2015-04-02 15:14:03 --> Record 13 DONE
2015-04-02 15:14:03 --> Record 14 DONE
2015-04-02 15:14:03 --> Record 15 DONE
2015-04-02 15:14:03 --> Record 16 DONE
2015-04-02 15:14:03 --> Record 17 DONE
2015-04-02 15:14:03 --> Record 18 DONE
2015-04-02 15:14:03 --> Record 19 DONE
2015-04-02 15:14:03 --> Record 20 DONE
2015-04-02 15:14:03 --> Record 21 DONE
2015-04-02 15:14:04 --> Record 22 DONE
2015-04-02 15:14:04 --> Record 23 DONE
2015-04-02 15:14:04 --> Record 24 DONE
2015-04-02 15:14:04 --> Record 25 DONE
2015-04-02 15:14:04 --> Record 26 DONE
2015-04-02 15:14:04 --> Record 27 DONE
2015-04-02 15:14:04 --> Record 28 DONE
2015-04-02 15:14:04 --> Record 29 DONE
2015-04-02 15:14:04 --> Record 30 DONE
2015-04-02 15:14:04 --> Record 31 DONE
2015-04-02 15:14:04 --> Record 32 DONE
2015-04-02 15:14:04 --> Record 33 DONE
2015-04-02 15:14:04 --> Record 34 DONE
2015-04-02 15:14:04 --> Record 35 DONE
2015-04-02 15:14:04 --> Record 36 DONE
2015-04-02 15:14:04 --> Record 37 DONE
2015-04-02 15:14:04 --> Record 38 DONE
2015-04-02 15:14:04 --> Record 39 DONE
2015-04-02 15:14:04 --> Record 40 DONE
2015-04-02 15:14:04 --> Record 41 DONE
2015-04-02 15:14:05 --> Record 42 DONE
2015-04-02 15:14:05 --> Record 43 DONE
2015-04-02 15:14:05 --> Record 44 DONE
2015-04-02 15:14:05 --> Record 45 DONE
2015-04-02 15:14:05 --> Record 46 DONE
2015-04-02 15:14:05 --> Record 47 DONE
2015-04-02 15:14:05 --> Record 48 DONE
2015-04-02 15:14:06 --> Record 49 DONE
2015-04-02 15:14:06 --> Record 50 DONE
2015-04-02 15:14:06 --> Record 51 DONE
2015-04-02 15:14:06 --> Record 52 DONE
2015-04-02 15:14:06 --> Record 53 DONE
2015-04-02 15:14:07 --> Record 54 DONE
2015-04-02 15:14:07 --> Record 55 DONE
2015-04-02 15:14:07 --> Record 56 DONE
2015-04-02 15:14:07 --> Record 57 DONE
2015-04-02 15:14:08 --> Record 58 DONE
2015-04-02 15:14:08 --> Record 59 DONE
2015-04-02 15:14:08 --> Record 60 DONE
2015-04-02 15:14:08 --> Record 61 DONE
2015-04-02 15:14:08 --> Record 62 DONE
2015-04-02 15:14:08 --> Record 63 DONE
2015-04-02 15:14:09 --> Record 64 DONE
2015-04-02 15:14:09 --> Record 65 DONE
2015-04-02 15:14:09 --> Record 66 DONE
2015-04-02 15:14:09 --> Record 67 DONE
2015-04-02 15:14:09 --> Record 68 DONE
2015-04-02 15:14:09 --> Record 69 DONE
2015-04-02 15:14:09 --> Record 70 DONE
2015-04-02 15:14:09 --> Record 71 DONE
2015-04-02 15:14:09 --> Record 72 DONE
2015-04-02 15:14:09 --> Record 73 DONE
2015-04-02 15:14:10 --> Record 74 DONE
2015-04-02 15:14:10 --> Record 75 DONE
2015-04-02 15:14:10 --> Record 76 DONE
2015-04-02 15:14:10 --> Record 77 DONE
2015-04-02 15:14:10 --> Record 78 DONE
2015-04-02 15:14:10 --> Record 79 DONE
2015-04-02 15:14:10 --> Record 80 DONE
2015-04-02 15:14:11 --> Record 81 DONE
2015-04-02 15:14:11 --> Record 82 DONE
2015-04-02 15:14:11 --> Record 83 DONE
2015-04-02 15:14:11 --> Record 84 DONE
2015-04-02 15:14:11 --> Record 85 DONE
2015-04-02 15:14:12 --> Record 86 DONE
2015-04-02 15:14:12 --> Record 87 DONE
2015-04-02 15:14:12 --> Record 88 DONE
2015-04-02 15:14:12 --> Record 89 DONE
2015-04-02 15:14:13 --> Record 90 DONE
2015-04-02 15:14:13 --> Record 91 DONE
2015-04-02 15:14:13 --> Record 92 DONE
2015-04-02 15:14:13 --> Record 93 DONE
2015-04-02 15:14:13 --> Record 94 DONE
2015-04-02 15:14:13 --> Record 95 DONE
2015-04-02 15:14:13 --> Record 96 DONE
2015-04-02 15:14:14 --> Record 97 DONE
2015-04-02 15:14:14 --> Record 98 DONE
2015-04-02 15:14:14 --> Record 99 DONE
2015-04-02 15:14:14 --> Record 100 DONE
2015-04-02 15:14:14 --> Record 101 DONE
2015-04-02 15:14:14 --> Record 102 DONE
2015-04-02 15:14:14 --> Record 103 DONE
2015-04-02 15:14:14 --> Record 104 DONE
2015-04-02 15:14:14 --> Record 105 DONE
2015-04-02 15:14:14 --> Record 106 DONE
2015-04-02 15:14:14 --> Record 107 DONE
2015-04-02 15:14:14 --> Record 108 DONE
2015-04-02 15:14:14 --> Record 109 DONE
2015-04-02 15:14:14 --> Record 110 DONE
2015-04-02 15:14:15 --> Record 111 DONE
2015-04-02 15:14:15 --> Record 112 DONE
2015-04-02 15:14:15 --> Record 113 DONE
2015-04-02 15:14:15 --> Record 114 DONE
2015-04-02 15:14:15 --> Record 115 DONE
2015-04-02 15:14:15 --> Record 116 DONE
2015-04-02 15:14:15 --> Record 117 DONE
2015-04-02 15:14:16 --> Record 118 DONE
2015-04-02 15:14:16 --> Record 119 DONE
2015-04-02 15:14:16 --> Record 120 DONE
2015-04-02 15:14:16 --> Record 121 DONE
2015-04-02 15:14:16 --> Record 122 DONE
2015-04-02 15:14:16 --> Record 123 DONE
2015-04-02 15:14:16 --> Record 124 DONE
2015-04-02 15:14:16 --> Record 125 DONE
2015-04-02 15:14:16 --> Record 126 DONE
2015-04-02 15:14:16 --> Record 127 DONE
2015-04-02 15:14:16 --> Record 128 DONE
2015-04-02 15:14:16 --> Record 129 DONE
2015-04-02 15:14:16 --> Record 130 DONE
2015-04-02 15:14:16 --> Record 131 DONE
2015-04-02 15:14:16 --> Record 132 DONE
2015-04-02 15:14:16 --> Record 133 DONE
2015-04-02 15:14:16 --> Record 134 DONE
2015-04-02 15:14:16 --> Record 135 DONE
2015-04-02 15:14:16 --> Record 136 DONE
2015-04-02 15:14:17 --> Record 137 DONE
2015-04-02 15:14:17 --> Record 138 DONE
2015-04-02 15:14:17 --> Record 139 DONE
2015-04-02 15:14:17 --> Record 140 DONE
2015-04-02 15:14:17 --> Record 141 DONE
2015-04-02 15:14:17 --> ERROR: in adding '/home/jnotarst/.virtualenvs/invenio2/var/tmp/bibdocfile_gvTast.csv' as a new format because of: A file for docid '107' already exists for the format '.csv'
2015-04-02 15:14:17 --> 
Traceback (most recent call last):
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py", line 477, in bibupload
    tmp_vers=tmp_vers, bibrecdocs=bibrecdocs)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py", line 2107, in elaborate_fft_tags
    assert(_add_new_format(bibdoc, url, docformat, docname, doctype, newname, description, comment, flags, timestamp, pretend=pretend))
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py", line 1740, in _add_new_format
    bibdoc.add_file_new_format(url, description=description, comment=comment, flags=flags, modification_date=modification_date)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibdocfile/api.py", line 2068, in add_file_new_format
    raise InvenioBibDocFileError, "A file for docid '%s' already exists for the format '%s'" % (str(self.id), docformat)
InvenioBibDocFileError: A file for docid '107' already exists for the format '.csv'
2015-04-02 15:14:17 -->    Stage 2 failed: ERROR: while elaborating FFT tags: A file for docid '107' already exists for the format '.csv'
2015-04-02 15:14:17 --> <record>
  <controlfield tag="001">142</controlfield>
  <controlfield tag="005">20150402151417.0</controlfield>
  <datafield tag="041" ind1=" " ind2=" ">
    <subfield code="a">eng</subfield>
  </datafield>
  <datafield tag="110" ind1=" " ind2=" ">
    <subfield code="a">United Nations</subfield>
  </datafield>
  <datafield tag="245" ind1=" " ind2=" ">
    <subfield code="a">World Population Prospects: The 2012 Revision</subfield>
  </datafield>
  <datafield tag="260" ind1=" " ind2=" ">
    <subfield code="a">New York, NY</subfield>
    <subfield code="b">United Nations</subfield>
    <subfield code="c">2013</subfield>
  </datafield>
  <datafield tag="980" ind1=" " ind2=" ">
    <subfield code="a">REPORT</subfield>
  </datafield>
</record>
2015-04-02 15:14:17 --> Uploading BDR and BDM fields
2015-04-02 15:14:17 --> Task stats: 142 input records, 0 updated, 141 inserted, 1 errors, 0 inserted to holding pen.  Time 20.54 sec.
2015-04-02 15:14:17 --> Task #1 finished. [DONE WITH ERRORS]
Extracting text for docid 86... DONE
Extracting text for docid 1... not needed
Extracting text for docid 2... not needed
Extracting text for docid 3... not needed
Extracting text for docid 4... not needed
Extracting text for docid 5... not needed
Extracting text for docid 6... not needed
Extracting text for docid 7... not needed
Extracting text for docid 8... DONE
Extracting text for docid 9... DONE
Extracting text for docid 10... DONE
Extracting text for docid 11... DONE
Extracting text for docid 12... DONE
Extracting text for docid 13... DONE
Extracting text for docid 14... DONE
Extracting text for docid 15... DONE
Extracting text for docid 16... DONE
Extracting text for docid 17... DONE
Extracting text for docid 18... DONE
Extracting text for docid 19... DONE
Extracting text for docid 20... DONE
Extracting text for docid 21... DONE
Extracting text for docid 22... DONE
Extracting text for docid 23... DONE
Extracting text for docid 24... DONE
Extracting text for docid 25... DONE
Extracting text for docid 26... DONE
Extracting text for docid 27... DONE
Extracting text for docid 28... DONE
Extracting text for docid 29... DONE
Extracting text for docid 30... DONE
Extracting text for docid 31... DONE
Extracting text for docid 32... DONE
Extracting text for docid 33... DONE
Extracting text for docid 34... DONE
Extracting text for docid 35... DONE
Extracting text for docid 36... DONE
Extracting text for docid 37... DONE
Extracting text for docid 38... DONE
Extracting text for docid 39... DONE
Extracting text for docid 40... DONE
Extracting text for docid 41... DONE
Extracting text for docid 42... DONE
Extracting text for docid 43... DONE
Extracting text for docid 44... DONE
Extracting text for docid 45... DONE
Extracting text for docid 46... DONE
Extracting text for docid 47... DONE
Extracting text for docid 48... DONE
Extracting text for docid 49... DONE
Extracting text for docid 50... not needed
Extracting text for docid 51... DONE
Extracting text for docid 52... DONE
Extracting text for docid 53... not needed
Extracting text for docid 54... DONE
Extracting text for docid 55... DONE
Extracting text for docid 56... DONE
Extracting text for docid 57... DONE
Extracting text for docid 58... DONE
Extracting text for docid 59... DONE
Extracting text for docid 60... DONE
Extracting text for docid 61... DONE
Extracting text for docid 62... DONE
Extracting text for docid 63... DONE
Extracting text for docid 64... DONE
Extracting text for docid 65... DONE
Extracting text for docid 66... DONE
Extracting text for docid 67... DONE
Extracting text for docid 68... DONE
Extracting text for docid 69... DONE
Extracting text for docid 70... DONE
Extracting text for docid 71... DONE
Extracting text for docid 72... DONE
Extracting text for docid 73... DONE
Extracting text for docid 74... DONE
Extracting text for docid 75... DONE
Extracting text for docid 76... DONE
Extracting text for docid 77... DONE
Extracting text for docid 78... DONE
Extracting text for docid 79... DONE
Extracting text for docid 80... DONE
Extracting text for docid 81... DONE
Extracting text for docid 82... DONE
Extracting text for docid 83... DONE
Extracting text for docid 84... DONE
Extracting text for docid 85... DONE
Extracting text for docid 86... not needed
Extracting text for docid 87... DONE
Extracting text for docid 88... not needed
Extracting text for docid 89... not needed
Extracting text for docid 90... not needed
Extracting text for docid 91... not needed
Extracting text for docid 92... not needed
Extracting text for docid 93... not needed
Extracting text for docid 94... not needed
Extracting text for docid 95... not needed
Extracting text for docid 96... not needed
Extracting text for docid 97... not needed
Extracting text for docid 98... not needed
Extracting text for docid 99... not needed
Extracting text for docid 100... not needed
Extracting text for docid 101... not needed
Extracting text for docid 102... not needed
Extracting text for docid 103... not needed
Extracting text for docid 104... not needed
Extracting text for docid 105... not needed
Extracting text for docid 106... not needed
Extracting text for docid 107... not needed
2015-04-02 15:14:48 --> Task #2 submitted.
2015-04-02 15:14:54 --> Task #2 started.
2015-04-02 15:14:54 --> Searching for records which should be reindexed...
2015-04-02 15:14:55 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibindex/engine.py:1978: UserWarning: Deprecated search_pattern(p=980__a:INSTITUTE, f=None, m=None) = intbitset([]).
  auth_recIDs = search_pattern(p='980__a:' + auth_type) \

2015-04-02 15:14:55 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibindex/engine.py:1978: UserWarning: Deprecated search_pattern(p=980__a:AUTHOR, f=None, m=None) = intbitset([]).
  auth_recIDs = search_pattern(p='980__a:' + auth_type) \

2015-04-02 15:14:55 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibindex/engine.py:1978: UserWarning: Deprecated search_pattern(p=980__a:JOURNAL, f=None, m=None) = intbitset([]).
  auth_recIDs = search_pattern(p='980__a:' + auth_type) \

2015-04-02 15:14:55 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibindex/engine.py:1978: UserWarning: Deprecated search_pattern(p=980__a:SUBJECT, f=None, m=None) = intbitset([]).
  auth_recIDs = search_pattern(p='980__a:' + auth_type) \

2015-04-02 15:14:55 --> idxWORD06F contains 0 words
2015-04-02 15:14:55 --> idxWORD06F is in consistent state
2015-04-02 15:14:55 --> idxWORD06F for 1-141 is in consistent state
2015-04-02 15:14:55 --> idxWORD06F adding records #1-#141 started
2015-04-02 15:14:56 --> idxWORD06F adding records #1-#141 started
2015-04-02 15:14:56 --> idxWORD06F normal wordtable flush started
2015-04-02 15:14:56 --> ...updating 7262 words into idxWORD06F started
2015-04-02 15:14:57 --> ......processed 726/7262 words
2015-04-02 15:14:57 --> ......processed 1452/7262 words
2015-04-02 15:14:57 --> ......processed 2178/7262 words
2015-04-02 15:14:57 --> ......processed 2904/7262 words
2015-04-02 15:14:58 --> ......processed 3630/7262 words
2015-04-02 15:14:58 --> ......processed 4356/7262 words
2015-04-02 15:14:58 --> ......processed 5082/7262 words
2015-04-02 15:14:58 --> ......processed 5808/7262 words
2015-04-02 15:14:58 --> ......processed 6534/7262 words
2015-04-02 15:14:59 --> ......processed 7260/7262 words
2015-04-02 15:14:59 --> ...updating 7262 words into idxWORD06R ended
2015-04-02 15:14:59 --> ...updating reverse table idxWORD06R started
2015-04-02 15:14:59 --> ...updating reverse table idxWORD06R ended
2015-04-02 15:14:59 --> idxWORD06F normal wordtable flush ended
2015-04-02 15:14:59 --> 48 records took 3.3 seconds to complete.(873 recs/min)
2015-04-02 15:14:59 --> Estimated runtime: 0.1 minutes
2015-04-02 15:14:59 --> idxWORD06F contains 7262 words
2015-04-02 15:14:59 --> idxWORD06F is in consistent state
2015-04-02 15:14:59 --> idxPAIR06F contains 0 words
2015-04-02 15:14:59 --> idxPAIR06F is in consistent state
2015-04-02 15:14:59 --> idxPAIR06F for 1-141 is in consistent state
2015-04-02 15:14:59 --> idxPAIR06F adding records #1-#141 started
2015-04-02 15:15:00 --> idxPAIR06F adding records #1-#141 started
2015-04-02 15:15:00 --> idxPAIR06F normal wordtable flush started
2015-04-02 15:15:00 --> ...updating 12452 words into idxPAIR06F started
2015-04-02 15:15:00 --> ......processed 1245/12452 words
2015-04-02 15:15:00 --> ......processed 2490/12452 words
2015-04-02 15:15:01 --> ......processed 3735/12452 words
2015-04-02 15:15:01 --> ......processed 4980/12452 words
2015-04-02 15:15:02 --> ......processed 6225/12452 words
2015-04-02 15:15:02 --> ......processed 7470/12452 words
2015-04-02 15:15:03 --> ......processed 8715/12452 words
2015-04-02 15:15:03 --> ......processed 9960/12452 words
2015-04-02 15:15:03 --> ......processed 11205/12452 words
2015-04-02 15:15:04 --> ......processed 12450/12452 words
2015-04-02 15:15:04 --> ...updating 12452 words into idxPAIR06R ended
2015-04-02 15:15:04 --> ...updating reverse table idxPAIR06R started
2015-04-02 15:15:04 --> ...updating reverse table idxPAIR06R ended
2015-04-02 15:15:04 --> idxPAIR06F normal wordtable flush ended
2015-04-02 15:15:04 --> 48 records took 5.2 seconds to complete.(552 recs/min)
2015-04-02 15:15:04 --> Estimated runtime: 0.2 minutes
2015-04-02 15:15:04 --> idxPAIR06F contains 12452 words
2015-04-02 15:15:04 --> idxPAIR06F is in consistent state
2015-04-02 15:15:04 --> idxPHRASE06F contains 0 words
2015-04-02 15:15:04 --> idxPHRASE06F is in consistent state
2015-04-02 15:15:04 --> idxPHRASE06F for 1-141 is in consistent state
2015-04-02 15:15:04 --> idxPHRASE06F adding records #1-#141 started
2015-04-02 15:15:04 --> idxPHRASE06F adding records #1-#141 started
2015-04-02 15:15:04 --> idxPHRASE06F normal wordtable flush started
2015-04-02 15:15:04 --> ...updating 4932 words into idxPHRASE06F started
2015-04-02 15:15:04 --> ......processed 493/4932 words
2015-04-02 15:15:05 --> ......processed 986/4932 words
2015-04-02 15:15:05 --> ......processed 1479/4932 words
2015-04-02 15:15:05 --> ......processed 1972/4932 words
2015-04-02 15:15:05 --> ......processed 2465/4932 words
2015-04-02 15:15:06 --> ......processed 2958/4932 words
2015-04-02 15:15:06 --> ......processed 3451/4932 words
2015-04-02 15:15:07 --> ......processed 3944/4932 words
2015-04-02 15:15:07 --> ......processed 4437/4932 words
2015-04-02 15:15:08 --> ......processed 4930/4932 words
2015-04-02 15:15:08 --> ...updating 4932 words into idxPHRASE06R ended
2015-04-02 15:15:08 --> ...updating reverse table idxPHRASE06R started
2015-04-02 15:15:08 --> ...updating reverse table idxPHRASE06R ended
2015-04-02 15:15:08 --> idxPHRASE06F normal wordtable flush ended
2015-04-02 15:15:08 --> 48 records took 4.1 seconds to complete.(700 recs/min)
2015-04-02 15:15:08 --> Estimated runtime: 0.1 minutes
2015-04-02 15:15:08 --> idxPHRASE06F contains 4927 words
2015-04-02 15:15:08 --> idxPHRASE06F is in consistent state
2015-04-02 15:15:08 --> idxWORD25F contains 0 words
2015-04-02 15:15:08 --> idxWORD25F is in consistent state
2015-04-02 15:15:08 --> idxWORD25F for 1-141 is in consistent state
2015-04-02 15:15:08 --> idxWORD25F adding records #1-#141 started
2015-04-02 15:15:08 --> idxWORD25F adding records #1-#141 started
2015-04-02 15:15:08 --> idxWORD25F normal wordtable flush started
2015-04-02 15:15:08 --> ...updating 0 words into idxWORD25F started
2015-04-02 15:15:08 --> ...updating 0 words into idxWORD25R ended
2015-04-02 15:15:08 --> ...updating reverse table idxWORD25R started
2015-04-02 15:15:08 --> ...updating reverse table idxWORD25R ended
2015-04-02 15:15:08 --> idxWORD25F normal wordtable flush ended
2015-04-02 15:15:08 --> 0 records took 0.0 seconds to complete.(0 recs/min)
2015-04-02 15:15:08 --> idxWORD25F contains 0 words
2015-04-02 15:15:08 --> idxWORD25F is in consistent state
2015-04-02 15:15:08 --> idxPAIR25F contains 0 words
2015-04-02 15:15:08 --> idxPAIR25F is in consistent state
2015-04-02 15:15:08 --> idxPAIR25F for 1-141 is in consistent state
2015-04-02 15:15:08 --> idxPAIR25F adding records #1-#141 started
2015-04-02 15:15:08 --> idxPAIR25F adding records #1-#141 started
2015-04-02 15:15:08 --> idxPAIR25F normal wordtable flush started
2015-04-02 15:15:08 --> ...updating 0 words into idxPAIR25F started
2015-04-02 15:15:08 --> ...updating 0 words into idxPAIR25R ended
2015-04-02 15:15:08 --> ...updating reverse table idxPAIR25R started
2015-04-02 15:15:08 --> ...updating reverse table idxPAIR25R ended
2015-04-02 15:15:08 --> idxPAIR25F normal wordtable flush ended
2015-04-02 15:15:08 --> 0 records took 0.0 seconds to complete.(0 recs/min)
2015-04-02 15:15:08 --> idxPAIR25F contains 0 words
2015-04-02 15:15:08 --> idxPAIR25F is in consistent state
2015-04-02 15:15:08 --> idxPHRASE25F contains 0 words
2015-04-02 15:15:08 --> idxPHRASE25F is in consistent state
2015-04-02 15:15:08 --> idxPHRASE25F for 1-141 is in consistent state
2015-04-02 15:15:08 --> idxPHRASE25F adding records #1-#141 started
2015-04-02 15:15:08 --> idxPHRASE25F adding records #1-#141 started
2015-04-02 15:15:08 --> idxPHRASE25F normal wordtable flush started
2015-04-02 15:15:08 --> ...updating 0 words into idxPHRASE25F started
2015-04-02 15:15:08 --> ...updating 0 words into idxPHRASE25R ended
2015-04-02 15:15:08 --> ...updating reverse table idxPHRASE25R started
2015-04-02 15:15:08 --> ...updating reverse table idxPHRASE25R ended
2015-04-02 15:15:08 --> idxPHRASE25F normal wordtable flush ended
2015-04-02 15:15:08 --> 0 records took 0.0 seconds to complete.(0 recs/min)
2015-04-02 15:15:08 --> idxPHRASE25F contains 0 words
2015-04-02 15:15:08 --> idxPHRASE25F is in consistent state
2015-04-02 15:15:08 --> idxWORD13F contains 0 words
2015-04-02 15:15:08 --> idxWORD13F is in consistent state
2015-04-02 15:15:08 --> idxWORD13F for 1-141 is in consistent state
2015-04-02 15:15:08 --> idxWORD13F adding records #1-#141 started
2015-04-02 15:15:08 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"AUTHOR|(SzGeCERN)aaa0005", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:08 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"INSTITUTE|(SzGeCERN)iii0002", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:08 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:749", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"39744", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:96536", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:513", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:1182", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:64142", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:5409", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:5482", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:14557", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:60616", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:5020", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:45799", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:65921", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:15220", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:76694", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibauthority/engine.py:184: UserWarning: Deprecated search_pattern(p=035__a:"PER:96316", f=None, m=None) = intbitset([]).
  '"' + control_no + '"')

2015-04-02 15:15:09 --> idxWORD13F adding records #1-#141 started
2015-04-02 15:15:09 --> idxWORD13F normal wordtable flush started
2015-04-02 15:15:09 --> ...updating 109 words into idxWORD13F started
2015-04-02 15:15:09 --> ......processed 10/109 words
2015-04-02 15:15:09 --> ......processed 20/109 words
2015-04-02 15:15:09 --> ......processed 30/109 words
2015-04-02 15:15:09 --> ......processed 40/109 words
2015-04-02 15:15:09 --> ......processed 50/109 words
2015-04-02 15:15:09 --> ......processed 60/109 words
2015-04-02 15:15:09 --> ......processed 70/109 words
2015-04-02 15:15:09 --> ......processed 80/109 words
2015-04-02 15:15:09 --> ......processed 90/109 words
2015-04-02 15:15:09 --> ......processed 100/109 words
2015-04-02 15:15:09 --> ...updating 109 words into idxWORD13R ended
2015-04-02 15:15:09 --> ...updating reverse table idxWORD13R started
2015-04-02 15:15:09 --> ...updating reverse table idxWORD13R ended
2015-04-02 15:15:09 --> idxWORD13F normal wordtable flush ended
2015-04-02 15:15:09 --> 79 records took 1.3 seconds to complete.(3577 recs/min)
2015-04-02 15:15:09 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:09 --> idxWORD13F contains 109 words
2015-04-02 15:15:09 --> idxWORD13F is in consistent state
2015-04-02 15:15:09 --> idxPAIR13F contains 0 words
2015-04-02 15:15:09 --> idxPAIR13F is in consistent state
2015-04-02 15:15:09 --> idxPAIR13F for 1-141 is in consistent state
2015-04-02 15:15:09 --> idxPAIR13F adding records #1-#141 started
2015-04-02 15:15:10 --> idxPAIR13F adding records #1-#141 started
2015-04-02 15:15:10 --> idxPAIR13F normal wordtable flush started
2015-04-02 15:15:10 --> ...updating 104 words into idxPAIR13F started
2015-04-02 15:15:10 --> ......processed 10/104 words
2015-04-02 15:15:10 --> ......processed 20/104 words
2015-04-02 15:15:10 --> ......processed 30/104 words
2015-04-02 15:15:10 --> ......processed 40/104 words
2015-04-02 15:15:10 --> ......processed 50/104 words
2015-04-02 15:15:10 --> ......processed 60/104 words
2015-04-02 15:15:10 --> ......processed 70/104 words
2015-04-02 15:15:10 --> ......processed 80/104 words
2015-04-02 15:15:10 --> ......processed 90/104 words
2015-04-02 15:15:10 --> ......processed 100/104 words
2015-04-02 15:15:10 --> ...updating 104 words into idxPAIR13R ended
2015-04-02 15:15:10 --> ...updating reverse table idxPAIR13R started
2015-04-02 15:15:10 --> ...updating reverse table idxPAIR13R ended
2015-04-02 15:15:10 --> idxPAIR13F normal wordtable flush ended
2015-04-02 15:15:10 --> 79 records took 1.0 seconds to complete.(4886 recs/min)
2015-04-02 15:15:10 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:10 --> idxPAIR13F contains 104 words
2015-04-02 15:15:10 --> idxPAIR13F is in consistent state
2015-04-02 15:15:10 --> idxPHRASE13F contains 0 words
2015-04-02 15:15:10 --> idxPHRASE13F is in consistent state
2015-04-02 15:15:10 --> idxPHRASE13F for 1-141 is in consistent state
2015-04-02 15:15:10 --> idxPHRASE13F adding records #1-#141 started
2015-04-02 15:15:11 --> idxPHRASE13F adding records #1-#141 started
2015-04-02 15:15:11 --> idxPHRASE13F normal wordtable flush started
2015-04-02 15:15:11 --> ...updating 63 words into idxPHRASE13F started
2015-04-02 15:15:11 --> ......processed 6/63 words
2015-04-02 15:15:11 --> ......processed 12/63 words
2015-04-02 15:15:11 --> ......processed 18/63 words
2015-04-02 15:15:11 --> ......processed 24/63 words
2015-04-02 15:15:11 --> ......processed 30/63 words
2015-04-02 15:15:11 --> ......processed 36/63 words
2015-04-02 15:15:11 --> ......processed 42/63 words
2015-04-02 15:15:11 --> ......processed 48/63 words
2015-04-02 15:15:11 --> ......processed 54/63 words
2015-04-02 15:15:11 --> ......processed 60/63 words
2015-04-02 15:15:11 --> ...updating 63 words into idxPHRASE13R ended
2015-04-02 15:15:11 --> ...updating reverse table idxPHRASE13R started
2015-04-02 15:15:11 --> ...updating reverse table idxPHRASE13R ended
2015-04-02 15:15:11 --> idxPHRASE13F normal wordtable flush ended
2015-04-02 15:15:11 --> 79 records took 0.9 seconds to complete.(5102 recs/min)
2015-04-02 15:15:11 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:11 --> idxPHRASE13F contains 63 words
2015-04-02 15:15:11 --> idxPHRASE13F is in consistent state
2015-04-02 15:15:11 --> idxWORD10F contains 0 words
2015-04-02 15:15:11 --> idxWORD10F is in consistent state
2015-04-02 15:15:11 --> idxWORD10F for 1-141 is in consistent state
2015-04-02 15:15:11 --> idxWORD10F adding records #1-#141 started
2015-04-02 15:15:11 --> idxWORD10F adding records #1-#141 started
2015-04-02 15:15:11 --> idxWORD10F normal wordtable flush started
2015-04-02 15:15:11 --> ...updating 30 words into idxWORD10F started
2015-04-02 15:15:11 --> ......processed 3/30 words
2015-04-02 15:15:11 --> ......processed 6/30 words
2015-04-02 15:15:11 --> ......processed 9/30 words
2015-04-02 15:15:11 --> ......processed 12/30 words
2015-04-02 15:15:11 --> ......processed 15/30 words
2015-04-02 15:15:11 --> ......processed 18/30 words
2015-04-02 15:15:11 --> ......processed 21/30 words
2015-04-02 15:15:11 --> ......processed 24/30 words
2015-04-02 15:15:11 --> ......processed 27/30 words
2015-04-02 15:15:11 --> ......processed 30/30 words
2015-04-02 15:15:11 --> ...updating 30 words into idxWORD10R ended
2015-04-02 15:15:11 --> ...updating reverse table idxWORD10R started
2015-04-02 15:15:11 --> ...updating reverse table idxWORD10R ended
2015-04-02 15:15:11 --> idxWORD10F normal wordtable flush ended
2015-04-02 15:15:11 --> 78 records took 0.1 seconds to complete.(84457 recs/min)
2015-04-02 15:15:11 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:11 --> idxWORD10F contains 30 words
2015-04-02 15:15:11 --> idxWORD10F is in consistent state
2015-04-02 15:15:11 --> idxPAIR10F contains 0 words
2015-04-02 15:15:11 --> idxPAIR10F is in consistent state
2015-04-02 15:15:11 --> idxPAIR10F for 1-141 is in consistent state
2015-04-02 15:15:11 --> idxPAIR10F adding records #1-#141 started
2015-04-02 15:15:11 --> idxPAIR10F adding records #1-#141 started
2015-04-02 15:15:11 --> idxPAIR10F normal wordtable flush started
2015-04-02 15:15:11 --> ...updating 1 words into idxPAIR10F started
2015-04-02 15:15:11 --> ...updating 1 words into idxPAIR10R ended
2015-04-02 15:15:11 --> ...updating reverse table idxPAIR10R started
2015-04-02 15:15:11 --> ...updating reverse table idxPAIR10R ended
2015-04-02 15:15:11 --> idxPAIR10F normal wordtable flush ended
2015-04-02 15:15:11 --> 78 records took 0.0 seconds to complete.(109944 recs/min)
2015-04-02 15:15:11 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:11 --> idxPAIR10F contains 1 words
2015-04-02 15:15:11 --> idxPAIR10F is in consistent state
2015-04-02 15:15:11 --> idxPHRASE10F contains 0 words
2015-04-02 15:15:11 --> idxPHRASE10F is in consistent state
2015-04-02 15:15:11 --> idxPHRASE10F for 1-141 is in consistent state
2015-04-02 15:15:11 --> idxPHRASE10F adding records #1-#141 started
2015-04-02 15:15:11 --> idxPHRASE10F adding records #1-#141 started
2015-04-02 15:15:11 --> idxPHRASE10F normal wordtable flush started
2015-04-02 15:15:11 --> ...updating 28 words into idxPHRASE10F started
2015-04-02 15:15:11 --> ......processed 2/28 words
2015-04-02 15:15:11 --> ......processed 4/28 words
2015-04-02 15:15:11 --> ......processed 6/28 words
2015-04-02 15:15:11 --> ......processed 8/28 words
2015-04-02 15:15:11 --> ......processed 10/28 words
2015-04-02 15:15:11 --> ......processed 12/28 words
2015-04-02 15:15:11 --> ......processed 14/28 words
2015-04-02 15:15:11 --> ......processed 16/28 words
2015-04-02 15:15:11 --> ......processed 18/28 words
2015-04-02 15:15:11 --> ......processed 20/28 words
2015-04-02 15:15:11 --> ......processed 22/28 words
2015-04-02 15:15:11 --> ......processed 24/28 words
2015-04-02 15:15:11 --> ......processed 26/28 words
2015-04-02 15:15:11 --> ......processed 28/28 words
2015-04-02 15:15:11 --> ...updating 28 words into idxPHRASE10R ended
2015-04-02 15:15:11 --> ...updating reverse table idxPHRASE10R started
2015-04-02 15:15:11 --> ...updating reverse table idxPHRASE10R ended
2015-04-02 15:15:11 --> idxPHRASE10F normal wordtable flush ended
2015-04-02 15:15:11 --> 78 records took 0.1 seconds to complete.(88299 recs/min)
2015-04-02 15:15:11 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:11 --> idxPHRASE10F contains 28 words
2015-04-02 15:15:11 --> idxPHRASE10F is in consistent state
2015-04-02 15:15:11 --> idxWORD20F contains 0 words
2015-04-02 15:15:11 --> idxWORD20F is in consistent state
2015-04-02 15:15:11 --> idxWORD20F for 1-141 is in consistent state
2015-04-02 15:15:11 --> idxWORD20F adding records #1-#141 started
2015-04-02 15:15:12 --> idxWORD20F adding records #1-#141 started
2015-04-02 15:15:12 --> idxWORD20F normal wordtable flush started
2015-04-02 15:15:12 --> ...updating 182 words into idxWORD20F started
2015-04-02 15:15:12 --> ......processed 18/182 words
2015-04-02 15:15:12 --> ......processed 36/182 words
2015-04-02 15:15:12 --> ......processed 54/182 words
2015-04-02 15:15:12 --> ......processed 72/182 words
2015-04-02 15:15:12 --> ......processed 90/182 words
2015-04-02 15:15:12 --> ......processed 108/182 words
2015-04-02 15:15:12 --> ......processed 126/182 words
2015-04-02 15:15:12 --> ......processed 144/182 words
2015-04-02 15:15:12 --> ......processed 162/182 words
2015-04-02 15:15:12 --> ......processed 180/182 words
2015-04-02 15:15:12 --> ...updating 182 words into idxWORD20R ended
2015-04-02 15:15:12 --> ...updating reverse table idxWORD20R started
2015-04-02 15:15:12 --> ...updating reverse table idxWORD20R ended
2015-04-02 15:15:12 --> idxWORD20F normal wordtable flush ended
2015-04-02 15:15:12 --> 114 records took 0.5 seconds to complete.(12909 recs/min)
2015-04-02 15:15:12 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:12 --> idxWORD20F contains 181 words
2015-04-02 15:15:12 --> idxWORD20F is in consistent state
2015-04-02 15:15:12 --> idxPAIR20F contains 0 words
2015-04-02 15:15:12 --> idxPAIR20F is in consistent state
2015-04-02 15:15:12 --> idxPAIR20F for 1-141 is in consistent state
2015-04-02 15:15:12 --> idxPAIR20F adding records #1-#141 started
2015-04-02 15:15:12 --> idxPAIR20F adding records #1-#141 started
2015-04-02 15:15:12 --> idxPAIR20F normal wordtable flush started
2015-04-02 15:15:12 --> ...updating 161 words into idxPAIR20F started
2015-04-02 15:15:12 --> ......processed 16/161 words
2015-04-02 15:15:12 --> ......processed 32/161 words
2015-04-02 15:15:12 --> ......processed 48/161 words
2015-04-02 15:15:12 --> ......processed 64/161 words
2015-04-02 15:15:12 --> ......processed 80/161 words
2015-04-02 15:15:12 --> ......processed 96/161 words
2015-04-02 15:15:12 --> ......processed 112/161 words
2015-04-02 15:15:12 --> ......processed 128/161 words
2015-04-02 15:15:12 --> ......processed 144/161 words
2015-04-02 15:15:12 --> ......processed 160/161 words
2015-04-02 15:15:12 --> ...updating 161 words into idxPAIR20R ended
2015-04-02 15:15:12 --> ...updating reverse table idxPAIR20R started
2015-04-02 15:15:12 --> ...updating reverse table idxPAIR20R ended
2015-04-02 15:15:12 --> idxPAIR20F normal wordtable flush ended
2015-04-02 15:15:13 --> 114 records took 0.5 seconds to complete.(13226 recs/min)
2015-04-02 15:15:13 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:13 --> idxPAIR20F contains 161 words
2015-04-02 15:15:13 --> idxPAIR20F is in consistent state
2015-04-02 15:15:13 --> idxPHRASE20F contains 0 words
2015-04-02 15:15:13 --> idxPHRASE20F is in consistent state
2015-04-02 15:15:13 --> idxPHRASE20F for 1-141 is in consistent state
2015-04-02 15:15:13 --> idxPHRASE20F adding records #1-#141 started
2015-04-02 15:15:13 --> idxPHRASE20F adding records #1-#141 started
2015-04-02 15:15:13 --> idxPHRASE20F normal wordtable flush started
2015-04-02 15:15:13 --> ...updating 693 words into idxPHRASE20F started
2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xCE' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xCE \xCE' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> ......processed 69/693 words
2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xD0 \xD0' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xCE \xCE\x9A\xCE\xB1...' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xD0 \xD0\xA1' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xD0 \xD0\x9F\xD1\x83...' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> ......processed 138/693 words
2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xD0' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xD0 \xD0 \xD0\x9F...' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> ......processed 207/693 words
2015-04-02 15:15:13 --> ......processed 276/693 words
2015-04-02 15:15:13 --> ......processed 345/693 words
2015-04-02 15:15:13 --> ......processed 414/693 words
2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xCE \xCE\xA0 \xCE...' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xD0 \xD0\xA1 \xD0...' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> ......processed 483/693 words
2015-04-02 15:15:13 --> ......processed 552/693 words
2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xCE \xCE\xA0' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> ......processed 621/693 words
2015-04-02 15:15:13 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py:268: Warning: Incorrect string value: '\xCE \xCE \xCE\x9A...' for column 'term' at row 1
  rc = cur.execute(sql, param)

2015-04-02 15:15:13 --> ......processed 690/693 words
2015-04-02 15:15:13 --> ...updating 693 words into idxPHRASE20R ended
2015-04-02 15:15:13 --> ...updating reverse table idxPHRASE20R started
2015-04-02 15:15:13 --> ...updating reverse table idxPHRASE20R ended
2015-04-02 15:15:13 --> idxPHRASE20F normal wordtable flush ended
2015-04-02 15:15:13 --> 114 records took 1.0 seconds to complete.(6960 recs/min)
2015-04-02 15:15:13 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:13 --> idxPHRASE20F contains 689 words
2015-04-02 15:15:13 --> idxPHRASE20F is in consistent state
2015-04-02 15:15:13 --> idxWORD04F contains 0 words
2015-04-02 15:15:13 --> idxWORD04F is in consistent state
2015-04-02 15:15:13 --> idxWORD04F for 1-141 is in consistent state
2015-04-02 15:15:13 --> idxWORD04F adding records #1-#141 started
2015-04-02 15:15:14 --> idxWORD04F adding records #1-#141 started
2015-04-02 15:15:14 --> idxWORD04F normal wordtable flush started
2015-04-02 15:15:14 --> ...updating 706 words into idxWORD04F started
2015-04-02 15:15:14 --> ......processed 70/706 words
2015-04-02 15:15:14 --> ......processed 140/706 words
2015-04-02 15:15:15 --> ......processed 210/706 words
2015-04-02 15:15:15 --> ......processed 280/706 words
2015-04-02 15:15:15 --> ......processed 350/706 words
2015-04-02 15:15:15 --> ......processed 420/706 words
2015-04-02 15:15:15 --> ......processed 490/706 words
2015-04-02 15:15:15 --> ......processed 560/706 words
2015-04-02 15:15:15 --> ......processed 630/706 words
2015-04-02 15:15:15 --> ......processed 700/706 words
2015-04-02 15:15:15 --> ...updating 706 words into idxWORD04R ended
2015-04-02 15:15:15 --> ...updating reverse table idxWORD04R started
2015-04-02 15:15:15 --> ...updating reverse table idxWORD04R ended
2015-04-02 15:15:15 --> idxWORD04F normal wordtable flush ended
2015-04-02 15:15:15 --> 141 records took 1.3 seconds to complete.(6718 recs/min)
2015-04-02 15:15:15 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:15 --> idxWORD04F contains 706 words
2015-04-02 15:15:15 --> idxWORD04F is in consistent state
2015-04-02 15:15:15 --> idxPAIR04F contains 0 words
2015-04-02 15:15:15 --> idxPAIR04F is in consistent state
2015-04-02 15:15:15 --> idxPAIR04F for 1-141 is in consistent state
2015-04-02 15:15:15 --> idxPAIR04F adding records #1-#141 started
2015-04-02 15:15:16 --> idxPAIR04F adding records #1-#141 started
2015-04-02 15:15:16 --> idxPAIR04F normal wordtable flush started
2015-04-02 15:15:16 --> ...updating 800 words into idxPAIR04F started
2015-04-02 15:15:16 --> ......processed 80/800 words
2015-04-02 15:15:16 --> ......processed 160/800 words
2015-04-02 15:15:16 --> ......processed 240/800 words
2015-04-02 15:15:16 --> ......processed 320/800 words
2015-04-02 15:15:16 --> ......processed 400/800 words
2015-04-02 15:15:16 --> ......processed 480/800 words
2015-04-02 15:15:16 --> ......processed 560/800 words
2015-04-02 15:15:16 --> ......processed 640/800 words
2015-04-02 15:15:16 --> ......processed 720/800 words
2015-04-02 15:15:16 --> ......processed 800/800 words
2015-04-02 15:15:16 --> ...updating 800 words into idxPAIR04R ended
2015-04-02 15:15:16 --> ...updating reverse table idxPAIR04R started
2015-04-02 15:15:16 --> ...updating reverse table idxPAIR04R ended
2015-04-02 15:15:16 --> idxPAIR04F normal wordtable flush ended
2015-04-02 15:15:16 --> 141 records took 1.3 seconds to complete.(6736 recs/min)
2015-04-02 15:15:16 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:16 --> idxPAIR04F contains 800 words
2015-04-02 15:15:16 --> idxPAIR04F is in consistent state
2015-04-02 15:15:16 --> idxPHRASE04F contains 0 words
2015-04-02 15:15:16 --> idxPHRASE04F is in consistent state
2015-04-02 15:15:16 --> idxPHRASE04F for 1-141 is in consistent state
2015-04-02 15:15:16 --> idxPHRASE04F adding records #1-#141 started
2015-04-02 15:15:17 --> idxPHRASE04F adding records #1-#141 started
2015-04-02 15:15:17 --> idxPHRASE04F normal wordtable flush started
2015-04-02 15:15:17 --> ...updating 2217 words into idxPHRASE04F started
2015-04-02 15:15:17 --> ......processed 221/2217 words
2015-04-02 15:15:17 --> ......processed 442/2217 words
2015-04-02 15:15:17 --> ......processed 663/2217 words
2015-04-02 15:15:17 --> ......processed 884/2217 words
2015-04-02 15:15:18 --> ......processed 1105/2217 words
2015-04-02 15:15:18 --> ......processed 1326/2217 words
2015-04-02 15:15:18 --> ......processed 1547/2217 words
2015-04-02 15:15:18 --> ......processed 1768/2217 words
2015-04-02 15:15:18 --> ......processed 1989/2217 words
2015-04-02 15:15:18 --> ......processed 2210/2217 words
2015-04-02 15:15:18 --> ...updating 2217 words into idxPHRASE04R ended
2015-04-02 15:15:18 --> ...updating reverse table idxPHRASE04R started
2015-04-02 15:15:18 --> ...updating reverse table idxPHRASE04R ended
2015-04-02 15:15:18 --> idxPHRASE04F normal wordtable flush ended
2015-04-02 15:15:18 --> 141 records took 2.1 seconds to complete.(3940 recs/min)
2015-04-02 15:15:18 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:18 --> idxPHRASE04F contains 2216 words
2015-04-02 15:15:18 --> idxPHRASE04F is in consistent state
2015-04-02 15:15:18 --> idxWORD11F contains 0 words
2015-04-02 15:15:18 --> idxWORD11F is in consistent state
2015-04-02 15:15:18 --> idxWORD11F for 1-141 is in consistent state
2015-04-02 15:15:18 --> idxWORD11F adding records #1-#141 started
2015-04-02 15:15:18 --> idxWORD11F adding records #1-#141 started
2015-04-02 15:15:18 --> idxWORD11F normal wordtable flush started
2015-04-02 15:15:18 --> ...updating 134 words into idxWORD11F started
2015-04-02 15:15:18 --> ......processed 13/134 words
2015-04-02 15:15:18 --> ......processed 26/134 words
2015-04-02 15:15:18 --> ......processed 39/134 words
2015-04-02 15:15:18 --> ......processed 52/134 words
2015-04-02 15:15:18 --> ......processed 65/134 words
2015-04-02 15:15:18 --> ......processed 78/134 words
2015-04-02 15:15:18 --> ......processed 91/134 words
2015-04-02 15:15:18 --> ......processed 104/134 words
2015-04-02 15:15:18 --> ......processed 117/134 words
2015-04-02 15:15:18 --> ......processed 130/134 words
2015-04-02 15:15:18 --> ...updating 134 words into idxWORD11R ended
2015-04-02 15:15:18 --> ...updating reverse table idxWORD11R started
2015-04-02 15:15:18 --> ...updating reverse table idxWORD11R ended
2015-04-02 15:15:18 --> idxWORD11F normal wordtable flush ended
2015-04-02 15:15:18 --> 141 records took 0.1 seconds to complete.(58010 recs/min)
2015-04-02 15:15:18 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:18 --> idxWORD11F contains 134 words
2015-04-02 15:15:18 --> idxWORD11F is in consistent state
2015-04-02 15:15:18 --> idxPAIR11F contains 0 words
2015-04-02 15:15:18 --> idxPAIR11F is in consistent state
2015-04-02 15:15:18 --> idxPAIR11F for 1-141 is in consistent state
2015-04-02 15:15:18 --> idxPAIR11F adding records #1-#141 started
2015-04-02 15:15:18 --> idxPAIR11F adding records #1-#141 started
2015-04-02 15:15:18 --> idxPAIR11F normal wordtable flush started
2015-04-02 15:15:18 --> ...updating 134 words into idxPAIR11F started
2015-04-02 15:15:18 --> ......processed 13/134 words
2015-04-02 15:15:18 --> ......processed 26/134 words
2015-04-02 15:15:18 --> ......processed 39/134 words
2015-04-02 15:15:18 --> ......processed 52/134 words
2015-04-02 15:15:18 --> ......processed 65/134 words
2015-04-02 15:15:18 --> ......processed 78/134 words
2015-04-02 15:15:18 --> ......processed 91/134 words
2015-04-02 15:15:18 --> ......processed 104/134 words
2015-04-02 15:15:18 --> ......processed 117/134 words
2015-04-02 15:15:18 --> ......processed 130/134 words
2015-04-02 15:15:18 --> ...updating 134 words into idxPAIR11R ended
2015-04-02 15:15:18 --> ...updating reverse table idxPAIR11R started
2015-04-02 15:15:18 --> ...updating reverse table idxPAIR11R ended
2015-04-02 15:15:18 --> idxPAIR11F normal wordtable flush ended
2015-04-02 15:15:18 --> 141 records took 0.1 seconds to complete.(66953 recs/min)
2015-04-02 15:15:18 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:18 --> idxPAIR11F contains 134 words
2015-04-02 15:15:18 --> idxPAIR11F is in consistent state
2015-04-02 15:15:18 --> idxPHRASE11F contains 0 words
2015-04-02 15:15:18 --> idxPHRASE11F is in consistent state
2015-04-02 15:15:18 --> idxPHRASE11F for 1-141 is in consistent state
2015-04-02 15:15:18 --> idxPHRASE11F adding records #1-#141 started
2015-04-02 15:15:19 --> idxPHRASE11F adding records #1-#141 started
2015-04-02 15:15:19 --> idxPHRASE11F normal wordtable flush started
2015-04-02 15:15:19 --> ...updating 134 words into idxPHRASE11F started
2015-04-02 15:15:19 --> ......processed 13/134 words
2015-04-02 15:15:19 --> ......processed 26/134 words
2015-04-02 15:15:19 --> ......processed 39/134 words
2015-04-02 15:15:19 --> ......processed 52/134 words
2015-04-02 15:15:19 --> ......processed 65/134 words
2015-04-02 15:15:19 --> ......processed 78/134 words
2015-04-02 15:15:19 --> ......processed 91/134 words
2015-04-02 15:15:19 --> ......processed 104/134 words
2015-04-02 15:15:19 --> ......processed 117/134 words
2015-04-02 15:15:19 --> ......processed 130/134 words
2015-04-02 15:15:19 --> ...updating 134 words into idxPHRASE11R ended
2015-04-02 15:15:19 --> ...updating reverse table idxPHRASE11R started
2015-04-02 15:15:19 --> ...updating reverse table idxPHRASE11R ended
2015-04-02 15:15:19 --> idxPHRASE11F normal wordtable flush ended
2015-04-02 15:15:19 --> 141 records took 0.1 seconds to complete.(64810 recs/min)
2015-04-02 15:15:19 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:19 --> idxPHRASE11F contains 134 words
2015-04-02 15:15:19 --> idxPHRASE11F is in consistent state
2015-04-02 15:15:19 --> idxWORD18F contains 0 words
2015-04-02 15:15:19 --> idxWORD18F is in consistent state
2015-04-02 15:15:19 --> idxWORD18F for 1-141 is in consistent state
2015-04-02 15:15:19 --> idxWORD18F adding records #1-#141 started
2015-04-02 15:15:19 --> idxWORD18F adding records #1-#141 started
2015-04-02 15:15:19 --> idxWORD18F normal wordtable flush started
2015-04-02 15:15:19 --> ...updating 12 words into idxWORD18F started
2015-04-02 15:15:19 --> ......processed 1/12 words
2015-04-02 15:15:19 --> ......processed 2/12 words
2015-04-02 15:15:19 --> ......processed 3/12 words
2015-04-02 15:15:19 --> ......processed 4/12 words
2015-04-02 15:15:19 --> ......processed 5/12 words
2015-04-02 15:15:19 --> ......processed 6/12 words
2015-04-02 15:15:19 --> ......processed 7/12 words
2015-04-02 15:15:19 --> ......processed 8/12 words
2015-04-02 15:15:19 --> ......processed 9/12 words
2015-04-02 15:15:19 --> ......processed 10/12 words
2015-04-02 15:15:19 --> ......processed 11/12 words
2015-04-02 15:15:19 --> ......processed 12/12 words
2015-04-02 15:15:19 --> ...updating 12 words into idxWORD18R ended
2015-04-02 15:15:19 --> ...updating reverse table idxWORD18R started
2015-04-02 15:15:19 --> ...updating reverse table idxWORD18R ended
2015-04-02 15:15:19 --> idxWORD18F normal wordtable flush ended
2015-04-02 15:15:19 --> 141 records took 0.2 seconds to complete.(36608 recs/min)
2015-04-02 15:15:19 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:19 --> idxWORD18F contains 12 words
2015-04-02 15:15:19 --> idxWORD18F is in consistent state
2015-04-02 15:15:19 --> idxPAIR18F contains 0 words
2015-04-02 15:15:19 --> idxPAIR18F is in consistent state
2015-04-02 15:15:19 --> idxPAIR18F for 1-141 is in consistent state
2015-04-02 15:15:19 --> idxPAIR18F adding records #1-#141 started
2015-04-02 15:15:19 --> idxPAIR18F adding records #1-#141 started
2015-04-02 15:15:19 --> idxPAIR18F normal wordtable flush started
2015-04-02 15:15:19 --> ...updating 12 words into idxPAIR18F started
2015-04-02 15:15:19 --> ......processed 1/12 words
2015-04-02 15:15:19 --> ......processed 2/12 words
2015-04-02 15:15:19 --> ......processed 3/12 words
2015-04-02 15:15:19 --> ......processed 4/12 words
2015-04-02 15:15:19 --> ......processed 5/12 words
2015-04-02 15:15:19 --> ......processed 6/12 words
2015-04-02 15:15:19 --> ......processed 7/12 words
2015-04-02 15:15:19 --> ......processed 8/12 words
2015-04-02 15:15:19 --> ......processed 9/12 words
2015-04-02 15:15:19 --> ......processed 10/12 words
2015-04-02 15:15:19 --> ......processed 11/12 words
2015-04-02 15:15:19 --> ......processed 12/12 words
2015-04-02 15:15:19 --> ...updating 12 words into idxPAIR18R ended
2015-04-02 15:15:19 --> ...updating reverse table idxPAIR18R started
2015-04-02 15:15:19 --> ...updating reverse table idxPAIR18R ended
2015-04-02 15:15:19 --> idxPAIR18F normal wordtable flush ended
2015-04-02 15:15:19 --> 141 records took 0.3 seconds to complete.(30924 recs/min)
2015-04-02 15:15:19 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:19 --> idxPAIR18F contains 12 words
2015-04-02 15:15:19 --> idxPAIR18F is in consistent state
2015-04-02 15:15:19 --> idxPHRASE18F contains 0 words
2015-04-02 15:15:19 --> idxPHRASE18F is in consistent state
2015-04-02 15:15:19 --> idxPHRASE18F for 1-141 is in consistent state
2015-04-02 15:15:19 --> idxPHRASE18F adding records #1-#141 started
2015-04-02 15:15:19 --> idxPHRASE18F adding records #1-#141 started
2015-04-02 15:15:19 --> idxPHRASE18F normal wordtable flush started
2015-04-02 15:15:19 --> ...updating 12 words into idxPHRASE18F started
2015-04-02 15:15:19 --> ......processed 1/12 words
2015-04-02 15:15:19 --> ......processed 2/12 words
2015-04-02 15:15:19 --> ......processed 3/12 words
2015-04-02 15:15:19 --> ......processed 4/12 words
2015-04-02 15:15:19 --> ......processed 5/12 words
2015-04-02 15:15:19 --> ......processed 6/12 words
2015-04-02 15:15:19 --> ......processed 7/12 words
2015-04-02 15:15:19 --> ......processed 8/12 words
2015-04-02 15:15:19 --> ......processed 9/12 words
2015-04-02 15:15:19 --> ......processed 10/12 words
2015-04-02 15:15:19 --> ......processed 11/12 words
2015-04-02 15:15:19 --> ......processed 12/12 words
2015-04-02 15:15:19 --> ...updating 12 words into idxPHRASE18R ended
2015-04-02 15:15:19 --> ...updating reverse table idxPHRASE18R started
2015-04-02 15:15:19 --> ...updating reverse table idxPHRASE18R ended
2015-04-02 15:15:19 --> idxPHRASE18F normal wordtable flush ended
2015-04-02 15:15:19 --> 141 records took 0.1 seconds to complete.(76981 recs/min)
2015-04-02 15:15:19 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:19 --> idxPHRASE18F contains 12 words
2015-04-02 15:15:19 --> idxPHRASE18F is in consistent state
2015-04-02 15:15:19 --> idxWORD16F contains 0 words
2015-04-02 15:15:19 --> idxWORD16F is in consistent state
2015-04-02 15:15:19 --> idxWORD16F for 1-141 is in consistent state
2015-04-02 15:15:19 --> idxWORD16F adding records #1-#141 started
2015-04-02 15:15:20 --> idxWORD16F adding records #1-#141 started
2015-04-02 15:15:20 --> idxWORD16F normal wordtable flush started
2015-04-02 15:15:20 --> ...updating 160 words into idxWORD16F started
2015-04-02 15:15:20 --> ......processed 16/160 words
2015-04-02 15:15:20 --> ......processed 32/160 words
2015-04-02 15:15:20 --> ......processed 48/160 words
2015-04-02 15:15:20 --> ......processed 64/160 words
2015-04-02 15:15:20 --> ......processed 80/160 words
2015-04-02 15:15:20 --> ......processed 96/160 words
2015-04-02 15:15:20 --> ......processed 112/160 words
2015-04-02 15:15:20 --> ......processed 128/160 words
2015-04-02 15:15:20 --> ......processed 144/160 words
2015-04-02 15:15:20 --> ......processed 160/160 words
2015-04-02 15:15:20 --> ...updating 160 words into idxWORD16R ended
2015-04-02 15:15:20 --> ...updating reverse table idxWORD16R started
2015-04-02 15:15:20 --> ...updating reverse table idxWORD16R ended
2015-04-02 15:15:20 --> idxWORD16F normal wordtable flush ended
2015-04-02 15:15:20 --> 141 records took 0.5 seconds to complete.(17029 recs/min)
2015-04-02 15:15:20 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:20 --> idxWORD16F contains 160 words
2015-04-02 15:15:20 --> idxWORD16F is in consistent state
2015-04-02 15:15:20 --> idxPAIR16F contains 0 words
2015-04-02 15:15:20 --> idxPAIR16F is in consistent state
2015-04-02 15:15:20 --> idxPAIR16F for 1-141 is in consistent state
2015-04-02 15:15:20 --> idxPAIR16F adding records #1-#141 started
2015-04-02 15:15:20 --> idxPAIR16F adding records #1-#141 started
2015-04-02 15:15:20 --> idxPAIR16F normal wordtable flush started
2015-04-02 15:15:20 --> ...updating 141 words into idxPAIR16F started
2015-04-02 15:15:20 --> ......processed 14/141 words
2015-04-02 15:15:20 --> ......processed 28/141 words
2015-04-02 15:15:20 --> ......processed 42/141 words
2015-04-02 15:15:20 --> ......processed 56/141 words
2015-04-02 15:15:20 --> ......processed 70/141 words
2015-04-02 15:15:20 --> ......processed 84/141 words
2015-04-02 15:15:20 --> ......processed 98/141 words
2015-04-02 15:15:20 --> ......processed 112/141 words
2015-04-02 15:15:20 --> ......processed 126/141 words
2015-04-02 15:15:20 --> ......processed 140/141 words
2015-04-02 15:15:20 --> ...updating 141 words into idxPAIR16R ended
2015-04-02 15:15:20 --> ...updating reverse table idxPAIR16R started
2015-04-02 15:15:20 --> ...updating reverse table idxPAIR16R ended
2015-04-02 15:15:20 --> idxPAIR16F normal wordtable flush ended
2015-04-02 15:15:20 --> 141 records took 0.5 seconds to complete.(17000 recs/min)
2015-04-02 15:15:20 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:20 --> idxPAIR16F contains 141 words
2015-04-02 15:15:20 --> idxPAIR16F is in consistent state
2015-04-02 15:15:20 --> idxPHRASE16F contains 0 words
2015-04-02 15:15:20 --> idxPHRASE16F is in consistent state
2015-04-02 15:15:20 --> idxPHRASE16F for 1-141 is in consistent state
2015-04-02 15:15:20 --> idxPHRASE16F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPHRASE16F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPHRASE16F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 489 words into idxPHRASE16F started
2015-04-02 15:15:21 --> ......processed 48/489 words
2015-04-02 15:15:21 --> ......processed 96/489 words
2015-04-02 15:15:21 --> ......processed 144/489 words
2015-04-02 15:15:21 --> ......processed 192/489 words
2015-04-02 15:15:21 --> ......processed 240/489 words
2015-04-02 15:15:21 --> ......processed 288/489 words
2015-04-02 15:15:21 --> ......processed 336/489 words
2015-04-02 15:15:21 --> ......processed 384/489 words
2015-04-02 15:15:21 --> ......processed 432/489 words
2015-04-02 15:15:21 --> ......processed 480/489 words
2015-04-02 15:15:21 --> ...updating 489 words into idxPHRASE16R ended
2015-04-02 15:15:21 --> ...updating reverse table idxPHRASE16R started
2015-04-02 15:15:21 --> ...updating reverse table idxPHRASE16R ended
2015-04-02 15:15:21 --> idxPHRASE16F normal wordtable flush ended
2015-04-02 15:15:21 --> 141 records took 0.6 seconds to complete.(13746 recs/min)
2015-04-02 15:15:21 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:21 --> idxPHRASE16F contains 487 words
2015-04-02 15:15:21 --> idxPHRASE16F is in consistent state
2015-04-02 15:15:21 --> idxWORD21F contains 0 words
2015-04-02 15:15:21 --> idxWORD21F is in consistent state
2015-04-02 15:15:21 --> idxWORD21F for 1-141 is in consistent state
2015-04-02 15:15:21 --> idxWORD21F adding records #1-#141 started
2015-04-02 15:15:21 --> idxWORD21F adding records #1-#141 started
2015-04-02 15:15:21 --> idxWORD21F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 67 words into idxWORD21F started
2015-04-02 15:15:21 --> ......processed 6/67 words
2015-04-02 15:15:21 --> ......processed 12/67 words
2015-04-02 15:15:21 --> ......processed 18/67 words
2015-04-02 15:15:21 --> ......processed 24/67 words
2015-04-02 15:15:21 --> ......processed 30/67 words
2015-04-02 15:15:21 --> ......processed 36/67 words
2015-04-02 15:15:21 --> ......processed 42/67 words
2015-04-02 15:15:21 --> ......processed 48/67 words
2015-04-02 15:15:21 --> ......processed 54/67 words
2015-04-02 15:15:21 --> ......processed 60/67 words
2015-04-02 15:15:21 --> ......processed 66/67 words
2015-04-02 15:15:21 --> ...updating 67 words into idxWORD21R ended
2015-04-02 15:15:21 --> ...updating reverse table idxWORD21R started
2015-04-02 15:15:21 --> ...updating reverse table idxWORD21R ended
2015-04-02 15:15:21 --> idxWORD21F normal wordtable flush ended
2015-04-02 15:15:21 --> 17 records took 0.1 seconds to complete.(10535 recs/min)
2015-04-02 15:15:21 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:21 --> idxWORD21F contains 67 words
2015-04-02 15:15:21 --> idxWORD21F is in consistent state
2015-04-02 15:15:21 --> idxPAIR21F contains 0 words
2015-04-02 15:15:21 --> idxPAIR21F is in consistent state
2015-04-02 15:15:21 --> idxPAIR21F for 1-141 is in consistent state
2015-04-02 15:15:21 --> idxPAIR21F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPAIR21F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPAIR21F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 52 words into idxPAIR21F started
2015-04-02 15:15:21 --> ......processed 5/52 words
2015-04-02 15:15:21 --> ......processed 10/52 words
2015-04-02 15:15:21 --> ......processed 15/52 words
2015-04-02 15:15:21 --> ......processed 20/52 words
2015-04-02 15:15:21 --> ......processed 25/52 words
2015-04-02 15:15:21 --> ......processed 30/52 words
2015-04-02 15:15:21 --> ......processed 35/52 words
2015-04-02 15:15:21 --> ......processed 40/52 words
2015-04-02 15:15:21 --> ......processed 45/52 words
2015-04-02 15:15:21 --> ......processed 50/52 words
2015-04-02 15:15:21 --> ...updating 52 words into idxPAIR21R ended
2015-04-02 15:15:21 --> ...updating reverse table idxPAIR21R started
2015-04-02 15:15:21 --> ...updating reverse table idxPAIR21R ended
2015-04-02 15:15:21 --> idxPAIR21F normal wordtable flush ended
2015-04-02 15:15:21 --> 17 records took 0.1 seconds to complete.(18369 recs/min)
2015-04-02 15:15:21 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:21 --> idxPAIR21F contains 52 words
2015-04-02 15:15:21 --> idxPAIR21F is in consistent state
2015-04-02 15:15:21 --> idxPHRASE21F contains 0 words
2015-04-02 15:15:21 --> idxPHRASE21F is in consistent state
2015-04-02 15:15:21 --> idxPHRASE21F for 1-141 is in consistent state
2015-04-02 15:15:21 --> idxPHRASE21F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPHRASE21F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPHRASE21F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 39 words into idxPHRASE21F started
2015-04-02 15:15:21 --> ......processed 3/39 words
2015-04-02 15:15:21 --> ......processed 6/39 words
2015-04-02 15:15:21 --> ......processed 9/39 words
2015-04-02 15:15:21 --> ......processed 12/39 words
2015-04-02 15:15:21 --> ......processed 15/39 words
2015-04-02 15:15:21 --> ......processed 18/39 words
2015-04-02 15:15:21 --> ......processed 21/39 words
2015-04-02 15:15:21 --> ......processed 24/39 words
2015-04-02 15:15:21 --> ......processed 27/39 words
2015-04-02 15:15:21 --> ......processed 30/39 words
2015-04-02 15:15:21 --> ......processed 33/39 words
2015-04-02 15:15:21 --> ......processed 36/39 words
2015-04-02 15:15:21 --> ......processed 39/39 words
2015-04-02 15:15:21 --> ...updating 39 words into idxPHRASE21R ended
2015-04-02 15:15:21 --> ...updating reverse table idxPHRASE21R started
2015-04-02 15:15:21 --> ...updating reverse table idxPHRASE21R ended
2015-04-02 15:15:21 --> idxPHRASE21F normal wordtable flush ended
2015-04-02 15:15:21 --> 17 records took 0.0 seconds to complete.(21094 recs/min)
2015-04-02 15:15:21 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:21 --> idxPHRASE21F contains 38 words
2015-04-02 15:15:21 --> idxPHRASE21F is in consistent state
2015-04-02 15:15:21 --> idxWORD24F contains 0 words
2015-04-02 15:15:21 --> idxWORD24F is in consistent state
2015-04-02 15:15:21 --> idxWORD24F for 1-141 is in consistent state
2015-04-02 15:15:21 --> idxWORD24F adding records #1-#141 started
2015-04-02 15:15:21 --> idxWORD24F adding records #1-#141 started
2015-04-02 15:15:21 --> idxWORD24F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 0 words into idxWORD24F started
2015-04-02 15:15:21 --> ...updating 0 words into idxWORD24R ended
2015-04-02 15:15:21 --> ...updating reverse table idxWORD24R started
2015-04-02 15:15:21 --> ...updating reverse table idxWORD24R ended
2015-04-02 15:15:21 --> idxWORD24F normal wordtable flush ended
2015-04-02 15:15:21 --> 0 records took 0.0 seconds to complete.(0 recs/min)
2015-04-02 15:15:21 --> idxWORD24F contains 0 words
2015-04-02 15:15:21 --> idxWORD24F is in consistent state
2015-04-02 15:15:21 --> idxPAIR24F contains 0 words
2015-04-02 15:15:21 --> idxPAIR24F is in consistent state
2015-04-02 15:15:21 --> idxPAIR24F for 1-141 is in consistent state
2015-04-02 15:15:21 --> idxPAIR24F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPAIR24F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPAIR24F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 0 words into idxPAIR24F started
2015-04-02 15:15:21 --> ...updating 0 words into idxPAIR24R ended
2015-04-02 15:15:21 --> ...updating reverse table idxPAIR24R started
2015-04-02 15:15:21 --> ...updating reverse table idxPAIR24R ended
2015-04-02 15:15:21 --> idxPAIR24F normal wordtable flush ended
2015-04-02 15:15:21 --> 0 records took 0.0 seconds to complete.(0 recs/min)
2015-04-02 15:15:21 --> idxPAIR24F contains 0 words
2015-04-02 15:15:21 --> idxPAIR24F is in consistent state
2015-04-02 15:15:21 --> idxPHRASE24F contains 0 words
2015-04-02 15:15:21 --> idxPHRASE24F is in consistent state
2015-04-02 15:15:21 --> idxPHRASE24F for 1-141 is in consistent state
2015-04-02 15:15:21 --> idxPHRASE24F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPHRASE24F adding records #1-#141 started
2015-04-02 15:15:21 --> idxPHRASE24F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 0 words into idxPHRASE24F started
2015-04-02 15:15:21 --> ...updating 0 words into idxPHRASE24R ended
2015-04-02 15:15:21 --> ...updating reverse table idxPHRASE24R started
2015-04-02 15:15:21 --> ...updating reverse table idxPHRASE24R ended
2015-04-02 15:15:21 --> idxPHRASE24F normal wordtable flush ended
2015-04-02 15:15:21 --> 0 records took 0.0 seconds to complete.(0 recs/min)
2015-04-02 15:15:21 --> idxPHRASE24F contains 0 words
2015-04-02 15:15:21 --> idxPHRASE24F is in consistent state
2015-04-02 15:15:21 --> idxWORD03F contains 0 words
2015-04-02 15:15:21 --> idxWORD03F is in consistent state
2015-04-02 15:15:21 --> idxWORD03F for 1-141 is in consistent state
2015-04-02 15:15:21 --> idxWORD03F adding records #1-#141 started
2015-04-02 15:15:21 --> idxWORD03F adding records #1-#141 started
2015-04-02 15:15:21 --> idxWORD03F normal wordtable flush started
2015-04-02 15:15:21 --> ...updating 4252 words into idxWORD03F started
2015-04-02 15:15:21 --> ......processed 425/4252 words
2015-04-02 15:15:22 --> ......processed 850/4252 words
2015-04-02 15:15:22 --> ......processed 1275/4252 words
2015-04-02 15:15:22 --> ......processed 1700/4252 words
2015-04-02 15:15:22 --> ......processed 2125/4252 words
2015-04-02 15:15:22 --> ......processed 2550/4252 words
2015-04-02 15:15:22 --> ......processed 2975/4252 words
2015-04-02 15:15:22 --> ......processed 3400/4252 words
2015-04-02 15:15:23 --> ......processed 3825/4252 words
2015-04-02 15:15:23 --> ......processed 4250/4252 words
2015-04-02 15:15:23 --> ...updating 4252 words into idxWORD03R ended
2015-04-02 15:15:23 --> ...updating reverse table idxWORD03R started
2015-04-02 15:15:23 --> ...updating reverse table idxWORD03R ended
2015-04-02 15:15:23 --> idxWORD03F normal wordtable flush ended
2015-04-02 15:15:23 --> 80 records took 1.6 seconds to complete.(3007 recs/min)
2015-04-02 15:15:23 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:23 --> idxWORD03F contains 4251 words
2015-04-02 15:15:23 --> idxWORD03F is in consistent state
2015-04-02 15:15:23 --> idxPAIR03F contains 0 words
2015-04-02 15:15:23 --> idxPAIR03F is in consistent state
2015-04-02 15:15:23 --> idxPAIR03F for 1-141 is in consistent state
2015-04-02 15:15:23 --> idxPAIR03F adding records #1-#141 started
2015-04-02 15:15:23 --> idxPAIR03F adding records #1-#141 started
2015-04-02 15:15:23 --> idxPAIR03F normal wordtable flush started
2015-04-02 15:15:23 --> ...updating 9923 words into idxPAIR03F started
2015-04-02 15:15:23 --> ......processed 992/9923 words
2015-04-02 15:15:24 --> ......processed 1984/9923 words
2015-04-02 15:15:24 --> ......processed 2976/9923 words
2015-04-02 15:15:24 --> ......processed 3968/9923 words
2015-04-02 15:15:25 --> ......processed 4960/9923 words
2015-04-02 15:15:25 --> ......processed 5952/9923 words
2015-04-02 15:15:26 --> ......processed 6944/9923 words
2015-04-02 15:15:26 --> ......processed 7936/9923 words
2015-04-02 15:15:26 --> ......processed 8928/9923 words
2015-04-02 15:15:27 --> ......processed 9920/9923 words
2015-04-02 15:15:27 --> ...updating 9923 words into idxPAIR03R ended
2015-04-02 15:15:27 --> ...updating reverse table idxPAIR03R started
2015-04-02 15:15:27 --> ...updating reverse table idxPAIR03R ended
2015-04-02 15:15:27 --> idxPAIR03F normal wordtable flush ended
2015-04-02 15:15:27 --> 80 records took 4.0 seconds to complete.(1191 recs/min)
2015-04-02 15:15:27 --> Estimated runtime: 0.1 minutes
2015-04-02 15:15:27 --> idxPAIR03F contains 9923 words
2015-04-02 15:15:27 --> idxPAIR03F is in consistent state
2015-04-02 15:15:27 --> idxPHRASE03F contains 0 words
2015-04-02 15:15:27 --> idxPHRASE03F is in consistent state
2015-04-02 15:15:27 --> idxPHRASE03F for 1-141 is in consistent state
2015-04-02 15:15:27 --> idxPHRASE03F adding records #1-#141 started
2015-04-02 15:15:27 --> idxPHRASE03F adding records #1-#141 started
2015-04-02 15:15:27 --> idxPHRASE03F normal wordtable flush started
2015-04-02 15:15:27 --> ...updating 81 words into idxPHRASE03F started
2015-04-02 15:15:27 --> ......processed 8/81 words
2015-04-02 15:15:27 --> ......processed 16/81 words
2015-04-02 15:15:27 --> ......processed 24/81 words
2015-04-02 15:15:27 --> ......processed 32/81 words
2015-04-02 15:15:27 --> ......processed 40/81 words
2015-04-02 15:15:27 --> ......processed 48/81 words
2015-04-02 15:15:27 --> ......processed 56/81 words
2015-04-02 15:15:27 --> ......processed 64/81 words
2015-04-02 15:15:27 --> ......processed 72/81 words
2015-04-02 15:15:27 --> ......processed 80/81 words
2015-04-02 15:15:27 --> ...updating 81 words into idxPHRASE03R ended
2015-04-02 15:15:27 --> ...updating reverse table idxPHRASE03R started
2015-04-02 15:15:27 --> ...updating reverse table idxPHRASE03R ended
2015-04-02 15:15:27 --> idxPHRASE03F normal wordtable flush ended
2015-04-02 15:15:27 --> 80 records took 0.1 seconds to complete.(56019 recs/min)
2015-04-02 15:15:27 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:27 --> idxPHRASE03F contains 81 words
2015-04-02 15:15:27 --> idxPHRASE03F is in consistent state
2015-04-02 15:15:27 --> idxWORD09F contains 0 words
2015-04-02 15:15:27 --> idxWORD09F is in consistent state
2015-04-02 15:15:27 --> idxWORD09F for 1-141 is in consistent state
2015-04-02 15:15:27 --> idxWORD09F adding records #1-#141 started
2015-04-02 15:15:33 --> idxWORD09F adding records #1-#141 started
2015-04-02 15:15:33 --> idxWORD09F normal wordtable flush started
2015-04-02 15:15:33 --> ...updating 43333 words into idxWORD09F started
2015-04-02 15:15:35 --> ......processed 4333/43333 words
2015-04-02 15:15:36 --> ......processed 8666/43333 words
2015-04-02 15:15:38 --> ......processed 12999/43333 words
2015-04-02 15:15:39 --> ......processed 17332/43333 words
2015-04-02 15:15:41 --> ......processed 21665/43333 words
2015-04-02 15:15:42 --> ......processed 25998/43333 words
2015-04-02 15:15:44 --> ......processed 30331/43333 words
2015-04-02 15:15:45 --> ......processed 34664/43333 words
2015-04-02 15:15:47 --> ......processed 38997/43333 words
2015-04-02 15:15:48 --> ......processed 43330/43333 words
2015-04-02 15:15:48 --> ...updating 43333 words into idxWORD09R ended
2015-04-02 15:15:48 --> ...updating reverse table idxWORD09R started
2015-04-02 15:15:48 --> ...updating reverse table idxWORD09R ended
2015-04-02 15:15:48 --> idxWORD09F normal wordtable flush ended
2015-04-02 15:15:48 --> 73 records took 21.6 seconds to complete.(203 recs/min)
2015-04-02 15:15:48 --> Estimated runtime: 0.3 minutes
2015-04-02 15:15:48 --> idxWORD09F contains 43289 words
2015-04-02 15:15:48 --> idxWORD09F is in consistent state
2015-04-02 15:15:48 --> idxPAIR09F contains 0 words
2015-04-02 15:15:48 --> idxPAIR09F is in consistent state
2015-04-02 15:15:48 --> idxPAIR09F for 1-141 is in consistent state
2015-04-02 15:15:48 --> idxPAIR09F adding records #1-#141 started
2015-04-02 15:15:49 --> idxPAIR09F adding records #1-#141 started
2015-04-02 15:15:49 --> idxPAIR09F normal wordtable flush started
2015-04-02 15:15:49 --> ...updating 0 words into idxPAIR09F started
2015-04-02 15:15:49 --> ...updating 0 words into idxPAIR09R ended
2015-04-02 15:15:49 --> ...updating reverse table idxPAIR09R started
2015-04-02 15:15:49 --> ...updating reverse table idxPAIR09R ended
2015-04-02 15:15:49 --> idxPAIR09F normal wordtable flush ended
2015-04-02 15:15:49 --> 73 records took 0.3 seconds to complete.(13558 recs/min)
2015-04-02 15:15:49 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:49 --> idxPAIR09F contains 0 words
2015-04-02 15:15:49 --> idxPAIR09F is in consistent state
2015-04-02 15:15:49 --> idxPHRASE09F contains 0 words
2015-04-02 15:15:49 --> idxPHRASE09F is in consistent state
2015-04-02 15:15:49 --> idxPHRASE09F for 1-141 is in consistent state
2015-04-02 15:15:49 --> idxPHRASE09F adding records #1-#141 started
2015-04-02 15:15:49 --> idxPHRASE09F adding records #1-#141 started
2015-04-02 15:15:49 --> idxPHRASE09F normal wordtable flush started
2015-04-02 15:15:49 --> ...updating 0 words into idxPHRASE09F started
2015-04-02 15:15:49 --> ...updating 0 words into idxPHRASE09R ended
2015-04-02 15:15:49 --> ...updating reverse table idxPHRASE09R started
2015-04-02 15:15:49 --> ...updating reverse table idxPHRASE09R ended
2015-04-02 15:15:49 --> idxPHRASE09F normal wordtable flush ended
2015-04-02 15:15:49 --> 73 records took 0.3 seconds to complete.(14211 recs/min)
2015-04-02 15:15:49 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:49 --> idxPHRASE09F contains 0 words
2015-04-02 15:15:49 --> idxPHRASE09F is in consistent state
2015-04-02 15:15:49 --> idxWORD14F contains 0 words
2015-04-02 15:15:49 --> idxWORD14F is in consistent state
2015-04-02 15:15:49 --> idxWORD14F for 1-141 is in consistent state
2015-04-02 15:15:49 --> idxWORD14F adding records #1-#141 started
2015-04-02 15:15:50 --> idxWORD14F adding records #1-#141 started
2015-04-02 15:15:50 --> idxWORD14F normal wordtable flush started
2015-04-02 15:15:50 --> ...updating 706 words into idxWORD14F started
2015-04-02 15:15:50 --> ......processed 70/706 words
2015-04-02 15:15:50 --> ......processed 140/706 words
2015-04-02 15:15:50 --> ......processed 210/706 words
2015-04-02 15:15:50 --> ......processed 280/706 words
2015-04-02 15:15:51 --> ......processed 350/706 words
2015-04-02 15:15:51 --> ......processed 420/706 words
2015-04-02 15:15:51 --> ......processed 490/706 words
2015-04-02 15:15:51 --> ......processed 560/706 words
2015-04-02 15:15:51 --> ......processed 630/706 words
2015-04-02 15:15:51 --> ......processed 700/706 words
2015-04-02 15:15:51 --> ...updating 706 words into idxWORD14R ended
2015-04-02 15:15:51 --> ...updating reverse table idxWORD14R started
2015-04-02 15:15:51 --> ...updating reverse table idxWORD14R ended
2015-04-02 15:15:51 --> idxWORD14F normal wordtable flush ended
2015-04-02 15:15:51 --> 141 records took 1.6 seconds to complete.(5455 recs/min)
2015-04-02 15:15:51 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:51 --> idxWORD14F contains 706 words
2015-04-02 15:15:51 --> idxWORD14F is in consistent state
2015-04-02 15:15:51 --> idxPAIR14F contains 0 words
2015-04-02 15:15:51 --> idxPAIR14F is in consistent state
2015-04-02 15:15:51 --> idxPAIR14F for 1-141 is in consistent state
2015-04-02 15:15:51 --> idxPAIR14F adding records #1-#141 started
2015-04-02 15:15:52 --> idxPAIR14F adding records #1-#141 started
2015-04-02 15:15:52 --> idxPAIR14F normal wordtable flush started
2015-04-02 15:15:52 --> ...updating 800 words into idxPAIR14F started
2015-04-02 15:15:52 --> ......processed 80/800 words
2015-04-02 15:15:52 --> ......processed 160/800 words
2015-04-02 15:15:52 --> ......processed 240/800 words
2015-04-02 15:15:52 --> ......processed 320/800 words
2015-04-02 15:15:52 --> ......processed 400/800 words
2015-04-02 15:15:52 --> ......processed 480/800 words
2015-04-02 15:15:52 --> ......processed 560/800 words
2015-04-02 15:15:52 --> ......processed 640/800 words
2015-04-02 15:15:52 --> ......processed 720/800 words
2015-04-02 15:15:52 --> ......processed 800/800 words
2015-04-02 15:15:52 --> ...updating 800 words into idxPAIR14R ended
2015-04-02 15:15:52 --> ...updating reverse table idxPAIR14R started
2015-04-02 15:15:52 --> ...updating reverse table idxPAIR14R ended
2015-04-02 15:15:52 --> idxPAIR14F normal wordtable flush ended
2015-04-02 15:15:52 --> 141 records took 1.2 seconds to complete.(7134 recs/min)
2015-04-02 15:15:52 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:52 --> idxPAIR14F contains 800 words
2015-04-02 15:15:52 --> idxPAIR14F is in consistent state
2015-04-02 15:15:52 --> idxPHRASE14F contains 0 words
2015-04-02 15:15:52 --> idxPHRASE14F is in consistent state
2015-04-02 15:15:52 --> idxPHRASE14F for 1-141 is in consistent state
2015-04-02 15:15:52 --> idxPHRASE14F adding records #1-#141 started
2015-04-02 15:15:53 --> idxPHRASE14F adding records #1-#141 started
2015-04-02 15:15:53 --> idxPHRASE14F normal wordtable flush started
2015-04-02 15:15:53 --> ...updating 641 words into idxPHRASE14F started
2015-04-02 15:15:53 --> ......processed 64/641 words
2015-04-02 15:15:53 --> ......processed 128/641 words
2015-04-02 15:15:53 --> ......processed 192/641 words
2015-04-02 15:15:53 --> ......processed 256/641 words
2015-04-02 15:15:53 --> ......processed 320/641 words
2015-04-02 15:15:53 --> ......processed 384/641 words
2015-04-02 15:15:53 --> ......processed 448/641 words
2015-04-02 15:15:53 --> ......processed 512/641 words
2015-04-02 15:15:53 --> ......processed 576/641 words
2015-04-02 15:15:54 --> ......processed 640/641 words
2015-04-02 15:15:54 --> ...updating 641 words into idxPHRASE14R ended
2015-04-02 15:15:54 --> ...updating reverse table idxPHRASE14R started
2015-04-02 15:15:54 --> ...updating reverse table idxPHRASE14R ended
2015-04-02 15:15:54 --> idxPHRASE14F normal wordtable flush ended
2015-04-02 15:15:54 --> 141 records took 1.7 seconds to complete.(4920 recs/min)
2015-04-02 15:15:54 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:54 --> idxPHRASE14F contains 641 words
2015-04-02 15:15:54 --> idxPHRASE14F is in consistent state
2015-04-02 15:15:54 --> idxWORD22F contains 0 words
2015-04-02 15:15:54 --> idxWORD22F is in consistent state
2015-04-02 15:15:54 --> idxWORD22F for 1-141 is in consistent state
2015-04-02 15:15:54 --> idxWORD22F adding records #1-#141 started
2015-04-02 15:15:54 --> idxWORD22F adding records #1-#141 started
2015-04-02 15:15:54 --> idxWORD22F normal wordtable flush started
2015-04-02 15:15:54 --> ...updating 7 words into idxWORD22F started
2015-04-02 15:15:54 --> ...updating 7 words into idxWORD22R ended
2015-04-02 15:15:54 --> ...updating reverse table idxWORD22R started
2015-04-02 15:15:54 --> ...updating reverse table idxWORD22R ended
2015-04-02 15:15:54 --> idxWORD22F normal wordtable flush ended
2015-04-02 15:15:54 --> 1 records took 0.2 seconds to complete.(303 recs/min)
2015-04-02 15:15:54 --> Estimated runtime: 0.5 minutes
2015-04-02 15:15:54 --> idxWORD22F contains 7 words
2015-04-02 15:15:54 --> idxWORD22F is in consistent state
2015-04-02 15:15:54 --> idxPAIR22F contains 0 words
2015-04-02 15:15:54 --> idxPAIR22F is in consistent state
2015-04-02 15:15:54 --> idxPAIR22F for 1-141 is in consistent state
2015-04-02 15:15:54 --> idxPAIR22F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPAIR22F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPAIR22F normal wordtable flush started
2015-04-02 15:15:54 --> ...updating 5 words into idxPAIR22F started
2015-04-02 15:15:54 --> ...updating 5 words into idxPAIR22R ended
2015-04-02 15:15:54 --> ...updating reverse table idxPAIR22R started
2015-04-02 15:15:54 --> ...updating reverse table idxPAIR22R ended
2015-04-02 15:15:54 --> idxPAIR22F normal wordtable flush ended
2015-04-02 15:15:54 --> 1 records took 0.0 seconds to complete.(2122 recs/min)
2015-04-02 15:15:54 --> Estimated runtime: 0.1 minutes
2015-04-02 15:15:54 --> idxPAIR22F contains 5 words
2015-04-02 15:15:54 --> idxPAIR22F is in consistent state
2015-04-02 15:15:54 --> idxPHRASE22F contains 0 words
2015-04-02 15:15:54 --> idxPHRASE22F is in consistent state
2015-04-02 15:15:54 --> idxPHRASE22F for 1-141 is in consistent state
2015-04-02 15:15:54 --> idxPHRASE22F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPHRASE22F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPHRASE22F normal wordtable flush started
2015-04-02 15:15:54 --> ...updating 3 words into idxPHRASE22F started
2015-04-02 15:15:54 --> ...updating 3 words into idxPHRASE22R ended
2015-04-02 15:15:54 --> ...updating reverse table idxPHRASE22R started
2015-04-02 15:15:54 --> ...updating reverse table idxPHRASE22R ended
2015-04-02 15:15:54 --> idxPHRASE22F normal wordtable flush ended
2015-04-02 15:15:54 --> 1 records took 0.0 seconds to complete.(1776 recs/min)
2015-04-02 15:15:54 --> Estimated runtime: 0.1 minutes
2015-04-02 15:15:54 --> idxPHRASE22F contains 3 words
2015-04-02 15:15:54 --> idxPHRASE22F is in consistent state
2015-04-02 15:15:54 --> idxWORD12F contains 0 words
2015-04-02 15:15:54 --> idxWORD12F is in consistent state
2015-04-02 15:15:54 --> idxWORD12F for 1-141 is in consistent state
2015-04-02 15:15:54 --> idxWORD12F adding records #1-#141 started
2015-04-02 15:15:54 --> idxWORD12F adding records #1-#141 started
2015-04-02 15:15:54 --> idxWORD12F normal wordtable flush started
2015-04-02 15:15:54 --> ...updating 32 words into idxWORD12F started
2015-04-02 15:15:54 --> ......processed 3/32 words
2015-04-02 15:15:54 --> ......processed 6/32 words
2015-04-02 15:15:54 --> ......processed 9/32 words
2015-04-02 15:15:54 --> ......processed 12/32 words
2015-04-02 15:15:54 --> ......processed 15/32 words
2015-04-02 15:15:54 --> ......processed 18/32 words
2015-04-02 15:15:54 --> ......processed 21/32 words
2015-04-02 15:15:54 --> ......processed 24/32 words
2015-04-02 15:15:54 --> ......processed 27/32 words
2015-04-02 15:15:54 --> ......processed 30/32 words
2015-04-02 15:15:54 --> ...updating 32 words into idxWORD12R ended
2015-04-02 15:15:54 --> ...updating reverse table idxWORD12R started
2015-04-02 15:15:54 --> ...updating reverse table idxWORD12R ended
2015-04-02 15:15:54 --> idxWORD12F normal wordtable flush ended
2015-04-02 15:15:54 --> 5 records took 0.0 seconds to complete.(11606 recs/min)
2015-04-02 15:15:54 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:54 --> idxWORD12F contains 32 words
2015-04-02 15:15:54 --> idxWORD12F is in consistent state
2015-04-02 15:15:54 --> idxPAIR12F contains 0 words
2015-04-02 15:15:54 --> idxPAIR12F is in consistent state
2015-04-02 15:15:54 --> idxPAIR12F for 1-141 is in consistent state
2015-04-02 15:15:54 --> idxPAIR12F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPAIR12F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPAIR12F normal wordtable flush started
2015-04-02 15:15:54 --> ...updating 31 words into idxPAIR12F started
2015-04-02 15:15:54 --> ......processed 3/31 words
2015-04-02 15:15:54 --> ......processed 6/31 words
2015-04-02 15:15:54 --> ......processed 9/31 words
2015-04-02 15:15:54 --> ......processed 12/31 words
2015-04-02 15:15:54 --> ......processed 15/31 words
2015-04-02 15:15:54 --> ......processed 18/31 words
2015-04-02 15:15:54 --> ......processed 21/31 words
2015-04-02 15:15:54 --> ......processed 24/31 words
2015-04-02 15:15:54 --> ......processed 27/31 words
2015-04-02 15:15:54 --> ......processed 30/31 words
2015-04-02 15:15:54 --> ...updating 31 words into idxPAIR12R ended
2015-04-02 15:15:54 --> ...updating reverse table idxPAIR12R started
2015-04-02 15:15:54 --> ...updating reverse table idxPAIR12R ended
2015-04-02 15:15:54 --> idxPAIR12F normal wordtable flush ended
2015-04-02 15:15:54 --> 5 records took 0.0 seconds to complete.(12404 recs/min)
2015-04-02 15:15:54 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:54 --> idxPAIR12F contains 31 words
2015-04-02 15:15:54 --> idxPAIR12F is in consistent state
2015-04-02 15:15:54 --> idxPHRASE12F contains 0 words
2015-04-02 15:15:54 --> idxPHRASE12F is in consistent state
2015-04-02 15:15:54 --> idxPHRASE12F for 1-141 is in consistent state
2015-04-02 15:15:54 --> idxPHRASE12F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPHRASE12F adding records #1-#141 started
2015-04-02 15:15:54 --> idxPHRASE12F normal wordtable flush started
2015-04-02 15:15:54 --> ...updating 8 words into idxPHRASE12F started
2015-04-02 15:15:54 --> ...updating 8 words into idxPHRASE12R ended
2015-04-02 15:15:54 --> ...updating reverse table idxPHRASE12R started
2015-04-02 15:15:54 --> ...updating reverse table idxPHRASE12R ended
2015-04-02 15:15:54 --> idxPHRASE12F normal wordtable flush ended
2015-04-02 15:15:54 --> 5 records took 0.0 seconds to complete.(34982 recs/min)
2015-04-02 15:15:54 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:54 --> idxPHRASE12F contains 8 words
2015-04-02 15:15:54 --> idxPHRASE12F is in consistent state
2015-04-02 15:15:54 --> idxWORD26F contains 0 words
2015-04-02 15:15:54 --> idxWORD26F is in consistent state
2015-04-02 15:15:54 --> idxWORD26F for 1-141 is in consistent state
2015-04-02 15:15:54 --> idxWORD26F adding records #1-#141 started
2015-04-02 15:15:56 --> idxWORD26F adding records #1-#141 started
2015-04-02 15:15:56 --> idxWORD26F normal wordtable flush started
2015-04-02 15:15:56 --> ...updating 2782 words into idxWORD26F started
2015-04-02 15:15:56 --> ......processed 278/2782 words
2015-04-02 15:15:56 --> ......processed 556/2782 words
2015-04-02 15:15:56 --> ......processed 834/2782 words
2015-04-02 15:15:56 --> ......processed 1112/2782 words
2015-04-02 15:15:56 --> ......processed 1390/2782 words
2015-04-02 15:15:56 --> ......processed 1668/2782 words
2015-04-02 15:15:57 --> ......processed 1946/2782 words
2015-04-02 15:15:57 --> ......processed 2224/2782 words
2015-04-02 15:15:57 --> ......processed 2502/2782 words
2015-04-02 15:15:57 --> ......processed 2780/2782 words
2015-04-02 15:15:57 --> ...updating 2782 words into idxWORD26R ended
2015-04-02 15:15:57 --> ...updating reverse table idxWORD26R started
2015-04-02 15:15:57 --> ...updating reverse table idxWORD26R ended
2015-04-02 15:15:57 --> idxWORD26F normal wordtable flush ended
2015-04-02 15:15:57 --> 141 records took 3.1 seconds to complete.(2764 recs/min)
2015-04-02 15:15:57 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:57 --> idxWORD26F contains 2780 words
2015-04-02 15:15:57 --> idxWORD26F is in consistent state
2015-04-02 15:15:57 --> idxPAIR26F contains 0 words
2015-04-02 15:15:57 --> idxPAIR26F is in consistent state
2015-04-02 15:15:57 --> idxPAIR26F for 1-141 is in consistent state
2015-04-02 15:15:57 --> idxPAIR26F adding records #1-#141 started
2015-04-02 15:15:58 --> idxPAIR26F adding records #1-#141 started
2015-04-02 15:15:58 --> idxPAIR26F normal wordtable flush started
2015-04-02 15:15:58 --> ...updating 2485 words into idxPAIR26F started
2015-04-02 15:15:58 --> ......processed 248/2485 words
2015-04-02 15:15:58 --> ......processed 496/2485 words
2015-04-02 15:15:58 --> ......processed 744/2485 words
2015-04-02 15:15:59 --> ......processed 992/2485 words
2015-04-02 15:15:59 --> ......processed 1240/2485 words
2015-04-02 15:15:59 --> ......processed 1488/2485 words
2015-04-02 15:15:59 --> ......processed 1736/2485 words
2015-04-02 15:15:59 --> ......processed 1984/2485 words
2015-04-02 15:15:59 --> ......processed 2232/2485 words
2015-04-02 15:15:59 --> ......processed 2480/2485 words
2015-04-02 15:15:59 --> ...updating 2485 words into idxPAIR26R ended
2015-04-02 15:15:59 --> ...updating reverse table idxPAIR26R started
2015-04-02 15:15:59 --> ...updating reverse table idxPAIR26R ended
2015-04-02 15:15:59 --> idxPAIR26F normal wordtable flush ended
2015-04-02 15:15:59 --> 141 records took 2.0 seconds to complete.(4232 recs/min)
2015-04-02 15:15:59 --> Estimated runtime: 0.0 minutes
2015-04-02 15:15:59 --> idxPAIR26F contains 2485 words
2015-04-02 15:15:59 --> idxPAIR26F is in consistent state
2015-04-02 15:15:59 --> idxPHRASE26F contains 0 words
2015-04-02 15:15:59 --> idxPHRASE26F is in consistent state
2015-04-02 15:15:59 --> idxPHRASE26F for 1-141 is in consistent state
2015-04-02 15:15:59 --> idxPHRASE26F adding records #1-#141 started
2015-04-02 15:16:00 --> idxPHRASE26F adding records #1-#141 started
2015-04-02 15:16:00 --> idxPHRASE26F normal wordtable flush started
2015-04-02 15:16:00 --> ...updating 1901 words into idxPHRASE26F started
2015-04-02 15:16:00 --> ......processed 190/1901 words
2015-04-02 15:16:00 --> ......processed 380/1901 words
2015-04-02 15:16:00 --> ......processed 570/1901 words
2015-04-02 15:16:00 --> ......processed 760/1901 words
2015-04-02 15:16:00 --> ......processed 950/1901 words
2015-04-02 15:16:01 --> ......processed 1140/1901 words
2015-04-02 15:16:01 --> ......processed 1330/1901 words
2015-04-02 15:16:01 --> ......processed 1520/1901 words
2015-04-02 15:16:01 --> ......processed 1710/1901 words
2015-04-02 15:16:01 --> ......processed 1900/1901 words
2015-04-02 15:16:01 --> ...updating 1901 words into idxPHRASE26R ended
2015-04-02 15:16:01 --> ...updating reverse table idxPHRASE26R started
2015-04-02 15:16:01 --> ...updating reverse table idxPHRASE26R ended
2015-04-02 15:16:01 --> idxPHRASE26F normal wordtable flush ended
2015-04-02 15:16:01 --> 141 records took 2.0 seconds to complete.(4337 recs/min)
2015-04-02 15:16:01 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:01 --> idxPHRASE26F contains 1898 words
2015-04-02 15:16:01 --> idxPHRASE26F is in consistent state
2015-04-02 15:16:01 --> idxWORD02F contains 0 words
2015-04-02 15:16:01 --> idxWORD02F is in consistent state
2015-04-02 15:16:01 --> idxWORD02F for 1-141 is in consistent state
2015-04-02 15:16:01 --> idxWORD02F adding records #1-#141 started
2015-04-02 15:16:04 --> idxWORD02F adding records #1-#141 started
2015-04-02 15:16:04 --> idxWORD02F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 26 words into idxWORD02F started
2015-04-02 15:16:04 --> ......processed 2/26 words
2015-04-02 15:16:04 --> ......processed 4/26 words
2015-04-02 15:16:04 --> ......processed 6/26 words
2015-04-02 15:16:04 --> ......processed 8/26 words
2015-04-02 15:16:04 --> ......processed 10/26 words
2015-04-02 15:16:04 --> ......processed 12/26 words
2015-04-02 15:16:04 --> ......processed 14/26 words
2015-04-02 15:16:04 --> ......processed 16/26 words
2015-04-02 15:16:04 --> ......processed 18/26 words
2015-04-02 15:16:04 --> ......processed 20/26 words
2015-04-02 15:16:04 --> ......processed 22/26 words
2015-04-02 15:16:04 --> ......processed 24/26 words
2015-04-02 15:16:04 --> ......processed 26/26 words
2015-04-02 15:16:04 --> ...updating 26 words into idxWORD02R ended
2015-04-02 15:16:04 --> ...updating reverse table idxWORD02R started
2015-04-02 15:16:04 --> ...updating reverse table idxWORD02R ended
2015-04-02 15:16:04 --> idxWORD02F normal wordtable flush ended
2015-04-02 15:16:04 --> 115 records took 2.8 seconds to complete.(2428 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxWORD02F contains 26 words
2015-04-02 15:16:04 --> idxWORD02F is in consistent state
2015-04-02 15:16:04 --> idxPAIR02F contains 0 words
2015-04-02 15:16:04 --> idxPAIR02F is in consistent state
2015-04-02 15:16:04 --> idxPAIR02F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxPAIR02F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPAIR02F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPAIR02F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 18 words into idxPAIR02F started
2015-04-02 15:16:04 --> ......processed 1/18 words
2015-04-02 15:16:04 --> ......processed 2/18 words
2015-04-02 15:16:04 --> ......processed 3/18 words
2015-04-02 15:16:04 --> ......processed 4/18 words
2015-04-02 15:16:04 --> ......processed 5/18 words
2015-04-02 15:16:04 --> ......processed 6/18 words
2015-04-02 15:16:04 --> ......processed 7/18 words
2015-04-02 15:16:04 --> ......processed 8/18 words
2015-04-02 15:16:04 --> ......processed 9/18 words
2015-04-02 15:16:04 --> ......processed 10/18 words
2015-04-02 15:16:04 --> ......processed 11/18 words
2015-04-02 15:16:04 --> ......processed 12/18 words
2015-04-02 15:16:04 --> ......processed 13/18 words
2015-04-02 15:16:04 --> ......processed 14/18 words
2015-04-02 15:16:04 --> ......processed 15/18 words
2015-04-02 15:16:04 --> ......processed 16/18 words
2015-04-02 15:16:04 --> ......processed 17/18 words
2015-04-02 15:16:04 --> ......processed 18/18 words
2015-04-02 15:16:04 --> ...updating 18 words into idxPAIR02R ended
2015-04-02 15:16:04 --> ...updating reverse table idxPAIR02R started
2015-04-02 15:16:04 --> ...updating reverse table idxPAIR02R ended
2015-04-02 15:16:04 --> idxPAIR02F normal wordtable flush ended
2015-04-02 15:16:04 --> 115 records took 0.3 seconds to complete.(26841 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxPAIR02F contains 18 words
2015-04-02 15:16:04 --> idxPAIR02F is in consistent state
2015-04-02 15:16:04 --> idxPHRASE02F contains 0 words
2015-04-02 15:16:04 --> idxPHRASE02F is in consistent state
2015-04-02 15:16:04 --> idxPHRASE02F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxPHRASE02F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPHRASE02F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPHRASE02F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 25 words into idxPHRASE02F started
2015-04-02 15:16:04 --> ......processed 2/25 words
2015-04-02 15:16:04 --> ......processed 4/25 words
2015-04-02 15:16:04 --> ......processed 6/25 words
2015-04-02 15:16:04 --> ......processed 8/25 words
2015-04-02 15:16:04 --> ......processed 10/25 words
2015-04-02 15:16:04 --> ......processed 12/25 words
2015-04-02 15:16:04 --> ......processed 14/25 words
2015-04-02 15:16:04 --> ......processed 16/25 words
2015-04-02 15:16:04 --> ......processed 18/25 words
2015-04-02 15:16:04 --> ......processed 20/25 words
2015-04-02 15:16:04 --> ......processed 22/25 words
2015-04-02 15:16:04 --> ......processed 24/25 words
2015-04-02 15:16:04 --> ...updating 25 words into idxPHRASE02R ended
2015-04-02 15:16:04 --> ...updating reverse table idxPHRASE02R started
2015-04-02 15:16:04 --> ...updating reverse table idxPHRASE02R ended
2015-04-02 15:16:04 --> idxPHRASE02F normal wordtable flush ended
2015-04-02 15:16:04 --> 115 records took 0.2 seconds to complete.(29036 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxPHRASE02F contains 25 words
2015-04-02 15:16:04 --> idxPHRASE02F is in consistent state
2015-04-02 15:16:04 --> idxWORD23F contains 0 words
2015-04-02 15:16:04 --> idxWORD23F is in consistent state
2015-04-02 15:16:04 --> idxWORD23F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxWORD23F adding records #1-#141 started
2015-04-02 15:16:04 --> idxWORD23F adding records #1-#141 started
2015-04-02 15:16:04 --> idxWORD23F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 25 words into idxWORD23F started
2015-04-02 15:16:04 --> ......processed 2/25 words
2015-04-02 15:16:04 --> ......processed 4/25 words
2015-04-02 15:16:04 --> ......processed 6/25 words
2015-04-02 15:16:04 --> ......processed 8/25 words
2015-04-02 15:16:04 --> ......processed 10/25 words
2015-04-02 15:16:04 --> ......processed 12/25 words
2015-04-02 15:16:04 --> ......processed 14/25 words
2015-04-02 15:16:04 --> ......processed 16/25 words
2015-04-02 15:16:04 --> ......processed 18/25 words
2015-04-02 15:16:04 --> ......processed 20/25 words
2015-04-02 15:16:04 --> ......processed 22/25 words
2015-04-02 15:16:04 --> ......processed 24/25 words
2015-04-02 15:16:04 --> ...updating 25 words into idxWORD23R ended
2015-04-02 15:16:04 --> ...updating reverse table idxWORD23R started
2015-04-02 15:16:04 --> ...updating reverse table idxWORD23R ended
2015-04-02 15:16:04 --> idxWORD23F normal wordtable flush ended
2015-04-02 15:16:04 --> 4 records took 0.0 seconds to complete.(6325 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxWORD23F contains 25 words
2015-04-02 15:16:04 --> idxWORD23F is in consistent state
2015-04-02 15:16:04 --> idxPAIR23F contains 0 words
2015-04-02 15:16:04 --> idxPAIR23F is in consistent state
2015-04-02 15:16:04 --> idxPAIR23F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxPAIR23F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPAIR23F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPAIR23F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 15 words into idxPAIR23F started
2015-04-02 15:16:04 --> ......processed 1/15 words
2015-04-02 15:16:04 --> ......processed 2/15 words
2015-04-02 15:16:04 --> ......processed 3/15 words
2015-04-02 15:16:04 --> ......processed 4/15 words
2015-04-02 15:16:04 --> ......processed 5/15 words
2015-04-02 15:16:04 --> ......processed 6/15 words
2015-04-02 15:16:04 --> ......processed 7/15 words
2015-04-02 15:16:04 --> ......processed 8/15 words
2015-04-02 15:16:04 --> ......processed 9/15 words
2015-04-02 15:16:04 --> ......processed 10/15 words
2015-04-02 15:16:04 --> ......processed 11/15 words
2015-04-02 15:16:04 --> ......processed 12/15 words
2015-04-02 15:16:04 --> ......processed 13/15 words
2015-04-02 15:16:04 --> ......processed 14/15 words
2015-04-02 15:16:04 --> ......processed 15/15 words
2015-04-02 15:16:04 --> ...updating 15 words into idxPAIR23R ended
2015-04-02 15:16:04 --> ...updating reverse table idxPAIR23R started
2015-04-02 15:16:04 --> ...updating reverse table idxPAIR23R ended
2015-04-02 15:16:04 --> idxPAIR23F normal wordtable flush ended
2015-04-02 15:16:04 --> 4 records took 0.0 seconds to complete.(6940 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxPAIR23F contains 15 words
2015-04-02 15:16:04 --> idxPAIR23F is in consistent state
2015-04-02 15:16:04 --> idxPHRASE23F contains 0 words
2015-04-02 15:16:04 --> idxPHRASE23F is in consistent state
2015-04-02 15:16:04 --> idxPHRASE23F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxPHRASE23F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPHRASE23F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPHRASE23F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 17 words into idxPHRASE23F started
2015-04-02 15:16:04 --> ......processed 1/17 words
2015-04-02 15:16:04 --> ......processed 2/17 words
2015-04-02 15:16:04 --> ......processed 3/17 words
2015-04-02 15:16:04 --> ......processed 4/17 words
2015-04-02 15:16:04 --> ......processed 5/17 words
2015-04-02 15:16:04 --> ......processed 6/17 words
2015-04-02 15:16:04 --> ......processed 7/17 words
2015-04-02 15:16:04 --> ......processed 8/17 words
2015-04-02 15:16:04 --> ......processed 9/17 words
2015-04-02 15:16:04 --> ......processed 10/17 words
2015-04-02 15:16:04 --> ......processed 11/17 words
2015-04-02 15:16:04 --> ......processed 12/17 words
2015-04-02 15:16:04 --> ......processed 13/17 words
2015-04-02 15:16:04 --> ......processed 14/17 words
2015-04-02 15:16:04 --> ......processed 15/17 words
2015-04-02 15:16:04 --> ......processed 16/17 words
2015-04-02 15:16:04 --> ......processed 17/17 words
2015-04-02 15:16:04 --> ...updating 17 words into idxPHRASE23R ended
2015-04-02 15:16:04 --> ...updating reverse table idxPHRASE23R started
2015-04-02 15:16:04 --> ...updating reverse table idxPHRASE23R ended
2015-04-02 15:16:04 --> idxPHRASE23F normal wordtable flush ended
2015-04-02 15:16:04 --> 4 records took 0.0 seconds to complete.(7077 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxPHRASE23F contains 17 words
2015-04-02 15:16:04 --> idxPHRASE23F is in consistent state
2015-04-02 15:16:04 --> idxWORD15F contains 0 words
2015-04-02 15:16:04 --> idxWORD15F is in consistent state
2015-04-02 15:16:04 --> idxWORD15F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxWORD15F adding records #1-#141 started
2015-04-02 15:16:04 --> idxWORD15F adding records #1-#141 started
2015-04-02 15:16:04 --> idxWORD15F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 9 words into idxWORD15F started
2015-04-02 15:16:04 --> ...updating 9 words into idxWORD15R ended
2015-04-02 15:16:04 --> ...updating reverse table idxWORD15R started
2015-04-02 15:16:04 --> ...updating reverse table idxWORD15R ended
2015-04-02 15:16:04 --> idxWORD15F normal wordtable flush ended
2015-04-02 15:16:04 --> 1 records took 0.0 seconds to complete.(5703 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxWORD15F contains 9 words
2015-04-02 15:16:04 --> idxWORD15F is in consistent state
2015-04-02 15:16:04 --> idxPAIR15F contains 0 words
2015-04-02 15:16:04 --> idxPAIR15F is in consistent state
2015-04-02 15:16:04 --> idxPAIR15F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxPAIR15F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPAIR15F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPAIR15F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 2 words into idxPAIR15F started
2015-04-02 15:16:04 --> ...updating 2 words into idxPAIR15R ended
2015-04-02 15:16:04 --> ...updating reverse table idxPAIR15R started
2015-04-02 15:16:04 --> ...updating reverse table idxPAIR15R ended
2015-04-02 15:16:04 --> idxPAIR15F normal wordtable flush ended
2015-04-02 15:16:04 --> 1 records took 0.0 seconds to complete.(11133 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxPAIR15F contains 2 words
2015-04-02 15:16:04 --> idxPAIR15F is in consistent state
2015-04-02 15:16:04 --> idxPHRASE15F contains 0 words
2015-04-02 15:16:04 --> idxPHRASE15F is in consistent state
2015-04-02 15:16:04 --> idxPHRASE15F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxPHRASE15F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPHRASE15F adding records #1-#141 started
2015-04-02 15:16:04 --> idxPHRASE15F normal wordtable flush started
2015-04-02 15:16:04 --> ...updating 6 words into idxPHRASE15F started
2015-04-02 15:16:04 --> ...updating 6 words into idxPHRASE15R ended
2015-04-02 15:16:04 --> ...updating reverse table idxPHRASE15R started
2015-04-02 15:16:04 --> ...updating reverse table idxPHRASE15R ended
2015-04-02 15:16:04 --> idxPHRASE15F normal wordtable flush ended
2015-04-02 15:16:04 --> 1 records took 0.0 seconds to complete.(10726 recs/min)
2015-04-02 15:16:04 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:04 --> idxPHRASE15F contains 6 words
2015-04-02 15:16:04 --> idxPHRASE15F is in consistent state
2015-04-02 15:16:04 --> idxWORD17F contains 0 words
2015-04-02 15:16:04 --> idxWORD17F is in consistent state
2015-04-02 15:16:04 --> idxWORD17F for 1-141 is in consistent state
2015-04-02 15:16:04 --> idxWORD17F adding records #1-#141 started
2015-04-02 15:16:05 --> idxWORD17F adding records #1-#141 started
2015-04-02 15:16:05 --> idxWORD17F normal wordtable flush started
2015-04-02 15:16:05 --> ...updating 160 words into idxWORD17F started
2015-04-02 15:16:05 --> ......processed 16/160 words
2015-04-02 15:16:05 --> ......processed 32/160 words
2015-04-02 15:16:05 --> ......processed 48/160 words
2015-04-02 15:16:05 --> ......processed 64/160 words
2015-04-02 15:16:05 --> ......processed 80/160 words
2015-04-02 15:16:05 --> ......processed 96/160 words
2015-04-02 15:16:05 --> ......processed 112/160 words
2015-04-02 15:16:05 --> ......processed 128/160 words
2015-04-02 15:16:05 --> ......processed 144/160 words
2015-04-02 15:16:05 --> ......processed 160/160 words
2015-04-02 15:16:05 --> ...updating 160 words into idxWORD17R ended
2015-04-02 15:16:05 --> ...updating reverse table idxWORD17R started
2015-04-02 15:16:05 --> ...updating reverse table idxWORD17R ended
2015-04-02 15:16:05 --> idxWORD17F normal wordtable flush ended
2015-04-02 15:16:05 --> 141 records took 0.3 seconds to complete.(26152 recs/min)
2015-04-02 15:16:05 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:05 --> idxWORD17F contains 160 words
2015-04-02 15:16:05 --> idxWORD17F is in consistent state
2015-04-02 15:16:05 --> idxPAIR17F contains 0 words
2015-04-02 15:16:05 --> idxPAIR17F is in consistent state
2015-04-02 15:16:05 --> idxPAIR17F for 1-141 is in consistent state
2015-04-02 15:16:05 --> idxPAIR17F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPAIR17F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPAIR17F normal wordtable flush started
2015-04-02 15:16:05 --> ...updating 141 words into idxPAIR17F started
2015-04-02 15:16:05 --> ......processed 14/141 words
2015-04-02 15:16:05 --> ......processed 28/141 words
2015-04-02 15:16:05 --> ......processed 42/141 words
2015-04-02 15:16:05 --> ......processed 56/141 words
2015-04-02 15:16:05 --> ......processed 70/141 words
2015-04-02 15:16:05 --> ......processed 84/141 words
2015-04-02 15:16:05 --> ......processed 98/141 words
2015-04-02 15:16:05 --> ......processed 112/141 words
2015-04-02 15:16:05 --> ......processed 126/141 words
2015-04-02 15:16:05 --> ......processed 140/141 words
2015-04-02 15:16:05 --> ...updating 141 words into idxPAIR17R ended
2015-04-02 15:16:05 --> ...updating reverse table idxPAIR17R started
2015-04-02 15:16:05 --> ...updating reverse table idxPAIR17R ended
2015-04-02 15:16:05 --> idxPAIR17F normal wordtable flush ended
2015-04-02 15:16:05 --> 141 records took 0.3 seconds to complete.(27587 recs/min)
2015-04-02 15:16:05 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:05 --> idxPAIR17F contains 141 words
2015-04-02 15:16:05 --> idxPAIR17F is in consistent state
2015-04-02 15:16:05 --> idxPHRASE17F contains 0 words
2015-04-02 15:16:05 --> idxPHRASE17F is in consistent state
2015-04-02 15:16:05 --> idxPHRASE17F for 1-141 is in consistent state
2015-04-02 15:16:05 --> idxPHRASE17F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPHRASE17F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPHRASE17F normal wordtable flush started
2015-04-02 15:16:05 --> ...updating 102 words into idxPHRASE17F started
2015-04-02 15:16:05 --> ......processed 10/102 words
2015-04-02 15:16:05 --> ......processed 20/102 words
2015-04-02 15:16:05 --> ......processed 30/102 words
2015-04-02 15:16:05 --> ......processed 40/102 words
2015-04-02 15:16:05 --> ......processed 50/102 words
2015-04-02 15:16:05 --> ......processed 60/102 words
2015-04-02 15:16:05 --> ......processed 70/102 words
2015-04-02 15:16:05 --> ......processed 80/102 words
2015-04-02 15:16:05 --> ......processed 90/102 words
2015-04-02 15:16:05 --> ......processed 100/102 words
2015-04-02 15:16:05 --> ...updating 102 words into idxPHRASE17R ended
2015-04-02 15:16:05 --> ...updating reverse table idxPHRASE17R started
2015-04-02 15:16:05 --> ...updating reverse table idxPHRASE17R ended
2015-04-02 15:16:05 --> idxPHRASE17F normal wordtable flush ended
2015-04-02 15:16:05 --> 141 records took 0.3 seconds to complete.(29415 recs/min)
2015-04-02 15:16:05 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:05 --> idxPHRASE17F contains 102 words
2015-04-02 15:16:05 --> idxPHRASE17F is in consistent state
2015-04-02 15:16:05 --> idxWORD05F contains 0 words
2015-04-02 15:16:05 --> idxWORD05F is in consistent state
2015-04-02 15:16:05 --> idxWORD05F for 1-141 is in consistent state
2015-04-02 15:16:05 --> idxWORD05F adding records #1-#141 started
2015-04-02 15:16:05 --> idxWORD05F adding records #1-#141 started
2015-04-02 15:16:05 --> idxWORD05F normal wordtable flush started
2015-04-02 15:16:05 --> ...updating 28 words into idxWORD05F started
2015-04-02 15:16:05 --> ......processed 2/28 words
2015-04-02 15:16:05 --> ......processed 4/28 words
2015-04-02 15:16:05 --> ......processed 6/28 words
2015-04-02 15:16:05 --> ......processed 8/28 words
2015-04-02 15:16:05 --> ......processed 10/28 words
2015-04-02 15:16:05 --> ......processed 12/28 words
2015-04-02 15:16:05 --> ......processed 14/28 words
2015-04-02 15:16:05 --> ......processed 16/28 words
2015-04-02 15:16:05 --> ......processed 18/28 words
2015-04-02 15:16:05 --> ......processed 20/28 words
2015-04-02 15:16:05 --> ......processed 22/28 words
2015-04-02 15:16:05 --> ......processed 24/28 words
2015-04-02 15:16:05 --> ......processed 26/28 words
2015-04-02 15:16:05 --> ......processed 28/28 words
2015-04-02 15:16:05 --> ...updating 28 words into idxWORD05R ended
2015-04-02 15:16:05 --> ...updating reverse table idxWORD05R started
2015-04-02 15:16:05 --> ...updating reverse table idxWORD05R ended
2015-04-02 15:16:05 --> idxWORD05F normal wordtable flush ended
2015-04-02 15:16:05 --> 9 records took 0.0 seconds to complete.(23992 recs/min)
2015-04-02 15:16:05 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:05 --> idxWORD05F contains 28 words
2015-04-02 15:16:05 --> idxWORD05F is in consistent state
2015-04-02 15:16:05 --> idxPAIR05F contains 0 words
2015-04-02 15:16:05 --> idxPAIR05F is in consistent state
2015-04-02 15:16:05 --> idxPAIR05F for 1-141 is in consistent state
2015-04-02 15:16:05 --> idxPAIR05F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPAIR05F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPAIR05F normal wordtable flush started
2015-04-02 15:16:05 --> ...updating 7 words into idxPAIR05F started
2015-04-02 15:16:05 --> ...updating 7 words into idxPAIR05R ended
2015-04-02 15:16:05 --> ...updating reverse table idxPAIR05R started
2015-04-02 15:16:05 --> ...updating reverse table idxPAIR05R ended
2015-04-02 15:16:05 --> idxPAIR05F normal wordtable flush ended
2015-04-02 15:16:05 --> 9 records took 0.0 seconds to complete.(53909 recs/min)
2015-04-02 15:16:05 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:05 --> idxPAIR05F contains 7 words
2015-04-02 15:16:05 --> idxPAIR05F is in consistent state
2015-04-02 15:16:05 --> idxPHRASE05F contains 0 words
2015-04-02 15:16:05 --> idxPHRASE05F is in consistent state
2015-04-02 15:16:05 --> idxPHRASE05F for 1-141 is in consistent state
2015-04-02 15:16:05 --> idxPHRASE05F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPHRASE05F adding records #1-#141 started
2015-04-02 15:16:05 --> idxPHRASE05F normal wordtable flush started
2015-04-02 15:16:05 --> ...updating 20 words into idxPHRASE05F started
2015-04-02 15:16:05 --> ......processed 2/20 words
2015-04-02 15:16:05 --> ......processed 4/20 words
2015-04-02 15:16:05 --> ......processed 6/20 words
2015-04-02 15:16:05 --> ......processed 8/20 words
2015-04-02 15:16:05 --> ......processed 10/20 words
2015-04-02 15:16:05 --> ......processed 12/20 words
2015-04-02 15:16:05 --> ......processed 14/20 words
2015-04-02 15:16:05 --> ......processed 16/20 words
2015-04-02 15:16:05 --> ......processed 18/20 words
2015-04-02 15:16:05 --> ......processed 20/20 words
2015-04-02 15:16:05 --> ...updating 20 words into idxPHRASE05R ended
2015-04-02 15:16:05 --> ...updating reverse table idxPHRASE05R started
2015-04-02 15:16:05 --> ...updating reverse table idxPHRASE05R ended
2015-04-02 15:16:05 --> idxPHRASE05F normal wordtable flush ended
2015-04-02 15:16:05 --> 9 records took 0.0 seconds to complete.(33229 recs/min)
2015-04-02 15:16:05 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:05 --> idxPHRASE05F contains 20 words
2015-04-02 15:16:05 --> idxPHRASE05F is in consistent state
2015-04-02 15:16:05 --> idxWORD08F contains 0 words
2015-04-02 15:16:05 --> idxWORD08F is in consistent state
2015-04-02 15:16:05 --> idxWORD08F for 1-141 is in consistent state
2015-04-02 15:16:05 --> idxWORD08F adding records #1-#141 started
2015-04-02 15:16:06 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/modules/knowledge/models.py:158: UserWarning: The function is deprecated. Please use the `KnwKBRVAL.query_kb_mappings()` instead. E.g. [(kval.m_value,) for kval in KnwKBRVAL.query_kb_mappings(kb_id).all()]
  warnings.warn("The function is deprecated. Please use the "

2015-04-02 15:16:06 --> Error: Cannot put word β with sign 1 for recID 59.
2015-04-02 15:16:06 --> idxWORD08F adding records #1-#141 started
2015-04-02 15:16:06 --> idxWORD08F normal wordtable flush started
2015-04-02 15:16:06 --> ...updating 707 words into idxWORD08F started
2015-04-02 15:16:06 --> ......processed 70/707 words
2015-04-02 15:16:06 --> ......processed 140/707 words
2015-04-02 15:16:06 --> ......processed 210/707 words
2015-04-02 15:16:06 --> ......processed 280/707 words
2015-04-02 15:16:06 --> ......processed 350/707 words
2015-04-02 15:16:06 --> ......processed 420/707 words
2015-04-02 15:16:06 --> ......processed 490/707 words
2015-04-02 15:16:06 --> ......processed 560/707 words
2015-04-02 15:16:06 --> ......processed 630/707 words
2015-04-02 15:16:06 --> ......processed 700/707 words
2015-04-02 15:16:06 --> ...updating 707 words into idxWORD08R ended
2015-04-02 15:16:06 --> ...updating reverse table idxWORD08R started
2015-04-02 15:16:06 --> ...updating reverse table idxWORD08R ended
2015-04-02 15:16:06 --> idxWORD08F normal wordtable flush ended
2015-04-02 15:16:06 --> 115 records took 1.0 seconds to complete.(7095 recs/min)
2015-04-02 15:16:06 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:06 --> idxWORD08F contains 707 words
2015-04-02 15:16:06 --> idxWORD08F is in consistent state
2015-04-02 15:16:06 --> idxPAIR08F contains 0 words
2015-04-02 15:16:06 --> idxPAIR08F is in consistent state
2015-04-02 15:16:06 --> idxPAIR08F for 1-141 is in consistent state
2015-04-02 15:16:06 --> idxPAIR08F adding records #1-#141 started
2015-04-02 15:16:07 --> idxPAIR08F adding records #1-#141 started
2015-04-02 15:16:07 --> idxPAIR08F normal wordtable flush started
2015-04-02 15:16:07 --> ...updating 858 words into idxPAIR08F started
2015-04-02 15:16:07 --> ......processed 85/858 words
2015-04-02 15:16:07 --> ......processed 170/858 words
2015-04-02 15:16:07 --> ......processed 255/858 words
2015-04-02 15:16:07 --> ......processed 340/858 words
2015-04-02 15:16:07 --> ......processed 425/858 words
2015-04-02 15:16:07 --> ......processed 510/858 words
2015-04-02 15:16:07 --> ......processed 595/858 words
2015-04-02 15:16:07 --> ......processed 680/858 words
2015-04-02 15:16:07 --> ......processed 765/858 words
2015-04-02 15:16:07 --> ......processed 850/858 words
2015-04-02 15:16:07 --> ...updating 858 words into idxPAIR08R ended
2015-04-02 15:16:07 --> ...updating reverse table idxPAIR08R started
2015-04-02 15:16:07 --> ...updating reverse table idxPAIR08R ended
2015-04-02 15:16:07 --> idxPAIR08F normal wordtable flush ended
2015-04-02 15:16:07 --> 115 records took 1.0 seconds to complete.(7041 recs/min)
2015-04-02 15:16:07 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:07 --> idxPAIR08F contains 858 words
2015-04-02 15:16:07 --> idxPAIR08F is in consistent state
2015-04-02 15:16:07 --> idxPHRASE08F contains 0 words
2015-04-02 15:16:07 --> idxPHRASE08F is in consistent state
2015-04-02 15:16:07 --> idxPHRASE08F for 1-141 is in consistent state
2015-04-02 15:16:07 --> idxPHRASE08F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPHRASE08F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPHRASE08F normal wordtable flush started
2015-04-02 15:16:08 --> ...updating 130 words into idxPHRASE08F started
2015-04-02 15:16:08 --> ......processed 13/130 words
2015-04-02 15:16:08 --> ......processed 26/130 words
2015-04-02 15:16:08 --> ......processed 39/130 words
2015-04-02 15:16:08 --> ......processed 52/130 words
2015-04-02 15:16:08 --> ......processed 65/130 words
2015-04-02 15:16:08 --> ......processed 78/130 words
2015-04-02 15:16:08 --> ......processed 91/130 words
2015-04-02 15:16:08 --> ......processed 104/130 words
2015-04-02 15:16:08 --> ......processed 117/130 words
2015-04-02 15:16:08 --> ......processed 130/130 words
2015-04-02 15:16:08 --> ...updating 130 words into idxPHRASE08R ended
2015-04-02 15:16:08 --> ...updating reverse table idxPHRASE08R started
2015-04-02 15:16:08 --> ...updating reverse table idxPHRASE08R ended
2015-04-02 15:16:08 --> idxPHRASE08F normal wordtable flush ended
2015-04-02 15:16:08 --> 115 records took 0.2 seconds to complete.(34383 recs/min)
2015-04-02 15:16:08 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:08 --> idxPHRASE08F contains 130 words
2015-04-02 15:16:08 --> idxPHRASE08F is in consistent state
2015-04-02 15:16:08 --> idxWORD07F contains 0 words
2015-04-02 15:16:08 --> idxWORD07F is in consistent state
2015-04-02 15:16:08 --> idxWORD07F for 1-141 is in consistent state
2015-04-02 15:16:08 --> idxWORD07F adding records #1-#141 started
2015-04-02 15:16:08 --> idxWORD07F adding records #1-#141 started
2015-04-02 15:16:08 --> idxWORD07F normal wordtable flush started
2015-04-02 15:16:08 --> ...updating 374 words into idxWORD07F started
2015-04-02 15:16:08 --> ......processed 37/374 words
2015-04-02 15:16:08 --> ......processed 74/374 words
2015-04-02 15:16:08 --> ......processed 111/374 words
2015-04-02 15:16:08 --> ......processed 148/374 words
2015-04-02 15:16:08 --> ......processed 185/374 words
2015-04-02 15:16:08 --> ......processed 222/374 words
2015-04-02 15:16:08 --> ......processed 259/374 words
2015-04-02 15:16:08 --> ......processed 296/374 words
2015-04-02 15:16:08 --> ......processed 333/374 words
2015-04-02 15:16:08 --> ......processed 370/374 words
2015-04-02 15:16:08 --> ...updating 374 words into idxWORD07R ended
2015-04-02 15:16:08 --> ...updating reverse table idxWORD07R started
2015-04-02 15:16:08 --> ...updating reverse table idxWORD07R ended
2015-04-02 15:16:08 --> idxWORD07F normal wordtable flush ended
2015-04-02 15:16:08 --> 89 records took 0.2 seconds to complete.(31652 recs/min)
2015-04-02 15:16:08 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:08 --> idxWORD07F contains 374 words
2015-04-02 15:16:08 --> idxWORD07F is in consistent state
2015-04-02 15:16:08 --> idxPAIR07F contains 0 words
2015-04-02 15:16:08 --> idxPAIR07F is in consistent state
2015-04-02 15:16:08 --> idxPAIR07F for 1-141 is in consistent state
2015-04-02 15:16:08 --> idxPAIR07F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPAIR07F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPAIR07F normal wordtable flush started
2015-04-02 15:16:08 --> ...updating 245 words into idxPAIR07F started
2015-04-02 15:16:08 --> ......processed 24/245 words
2015-04-02 15:16:08 --> ......processed 48/245 words
2015-04-02 15:16:08 --> ......processed 72/245 words
2015-04-02 15:16:08 --> ......processed 96/245 words
2015-04-02 15:16:08 --> ......processed 120/245 words
2015-04-02 15:16:08 --> ......processed 144/245 words
2015-04-02 15:16:08 --> ......processed 168/245 words
2015-04-02 15:16:08 --> ......processed 192/245 words
2015-04-02 15:16:08 --> ......processed 216/245 words
2015-04-02 15:16:08 --> ......processed 240/245 words
2015-04-02 15:16:08 --> ...updating 245 words into idxPAIR07R ended
2015-04-02 15:16:08 --> ...updating reverse table idxPAIR07R started
2015-04-02 15:16:08 --> ...updating reverse table idxPAIR07R ended
2015-04-02 15:16:08 --> idxPAIR07F normal wordtable flush ended
2015-04-02 15:16:08 --> 89 records took 0.1 seconds to complete.(41493 recs/min)
2015-04-02 15:16:08 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:08 --> idxPAIR07F contains 245 words
2015-04-02 15:16:08 --> idxPAIR07F is in consistent state
2015-04-02 15:16:08 --> idxPHRASE07F contains 0 words
2015-04-02 15:16:08 --> idxPHRASE07F is in consistent state
2015-04-02 15:16:08 --> idxPHRASE07F for 1-141 is in consistent state
2015-04-02 15:16:08 --> idxPHRASE07F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPHRASE07F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPHRASE07F normal wordtable flush started
2015-04-02 15:16:08 --> ...updating 138 words into idxPHRASE07F started
2015-04-02 15:16:08 --> ......processed 13/138 words
2015-04-02 15:16:08 --> ......processed 26/138 words
2015-04-02 15:16:08 --> ......processed 39/138 words
2015-04-02 15:16:08 --> ......processed 52/138 words
2015-04-02 15:16:08 --> ......processed 65/138 words
2015-04-02 15:16:08 --> ......processed 78/138 words
2015-04-02 15:16:08 --> ......processed 91/138 words
2015-04-02 15:16:08 --> ......processed 104/138 words
2015-04-02 15:16:08 --> ......processed 117/138 words
2015-04-02 15:16:08 --> ......processed 130/138 words
2015-04-02 15:16:08 --> ...updating 138 words into idxPHRASE07R ended
2015-04-02 15:16:08 --> ...updating reverse table idxPHRASE07R started
2015-04-02 15:16:08 --> ...updating reverse table idxPHRASE07R ended
2015-04-02 15:16:08 --> idxPHRASE07F normal wordtable flush ended
2015-04-02 15:16:08 --> 89 records took 0.1 seconds to complete.(59272 recs/min)
2015-04-02 15:16:08 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:08 --> idxPHRASE07F contains 138 words
2015-04-02 15:16:08 --> idxPHRASE07F is in consistent state
2015-04-02 15:16:08 --> idxWORD19F contains 0 words
2015-04-02 15:16:08 --> idxWORD19F is in consistent state
2015-04-02 15:16:08 --> idxWORD19F for 1-141 is in consistent state
2015-04-02 15:16:08 --> idxWORD19F adding records #1-#141 started
2015-04-02 15:16:08 --> idxWORD19F adding records #1-#141 started
2015-04-02 15:16:08 --> idxWORD19F normal wordtable flush started
2015-04-02 15:16:08 --> ...updating 707 words into idxWORD19F started
2015-04-02 15:16:08 --> ......processed 70/707 words
2015-04-02 15:16:08 --> ......processed 140/707 words
2015-04-02 15:16:08 --> ......processed 210/707 words
2015-04-02 15:16:08 --> ......processed 280/707 words
2015-04-02 15:16:08 --> ......processed 350/707 words
2015-04-02 15:16:08 --> ......processed 420/707 words
2015-04-02 15:16:08 --> ......processed 490/707 words
2015-04-02 15:16:08 --> ......processed 560/707 words
2015-04-02 15:16:08 --> ......processed 630/707 words
2015-04-02 15:16:08 --> ......processed 700/707 words
2015-04-02 15:16:08 --> ...updating 707 words into idxWORD19R ended
2015-04-02 15:16:08 --> ...updating reverse table idxWORD19R started
2015-04-02 15:16:08 --> ...updating reverse table idxWORD19R ended
2015-04-02 15:16:08 --> idxWORD19F normal wordtable flush ended
2015-04-02 15:16:08 --> 115 records took 0.3 seconds to complete.(23963 recs/min)
2015-04-02 15:16:08 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:08 --> idxWORD19F contains 707 words
2015-04-02 15:16:08 --> idxWORD19F is in consistent state
2015-04-02 15:16:08 --> idxPAIR19F contains 0 words
2015-04-02 15:16:08 --> idxPAIR19F is in consistent state
2015-04-02 15:16:08 --> idxPAIR19F for 1-141 is in consistent state
2015-04-02 15:16:08 --> idxPAIR19F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPAIR19F adding records #1-#141 started
2015-04-02 15:16:08 --> idxPAIR19F normal wordtable flush started
2015-04-02 15:16:08 --> ...updating 858 words into idxPAIR19F started
2015-04-02 15:16:08 --> ......processed 85/858 words
2015-04-02 15:16:08 --> ......processed 170/858 words
2015-04-02 15:16:09 --> ......processed 255/858 words
2015-04-02 15:16:09 --> ......processed 340/858 words
2015-04-02 15:16:09 --> ......processed 425/858 words
2015-04-02 15:16:09 --> ......processed 510/858 words
2015-04-02 15:16:09 --> ......processed 595/858 words
2015-04-02 15:16:09 --> ......processed 680/858 words
2015-04-02 15:16:09 --> ......processed 765/858 words
2015-04-02 15:16:09 --> ......processed 850/858 words
2015-04-02 15:16:09 --> ...updating 858 words into idxPAIR19R ended
2015-04-02 15:16:09 --> ...updating reverse table idxPAIR19R started
2015-04-02 15:16:09 --> ...updating reverse table idxPAIR19R ended
2015-04-02 15:16:09 --> idxPAIR19F normal wordtable flush ended
2015-04-02 15:16:09 --> 115 records took 0.5 seconds to complete.(14417 recs/min)
2015-04-02 15:16:09 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:09 --> idxPAIR19F contains 858 words
2015-04-02 15:16:09 --> idxPAIR19F is in consistent state
2015-04-02 15:16:09 --> idxPHRASE19F contains 0 words
2015-04-02 15:16:09 --> idxPHRASE19F is in consistent state
2015-04-02 15:16:09 --> idxPHRASE19F for 1-141 is in consistent state
2015-04-02 15:16:09 --> idxPHRASE19F adding records #1-#141 started
2015-04-02 15:16:09 --> idxPHRASE19F adding records #1-#141 started
2015-04-02 15:16:09 --> idxPHRASE19F normal wordtable flush started
2015-04-02 15:16:09 --> ...updating 130 words into idxPHRASE19F started
2015-04-02 15:16:09 --> ......processed 13/130 words
2015-04-02 15:16:09 --> ......processed 26/130 words
2015-04-02 15:16:09 --> ......processed 39/130 words
2015-04-02 15:16:09 --> ......processed 52/130 words
2015-04-02 15:16:09 --> ......processed 65/130 words
2015-04-02 15:16:09 --> ......processed 78/130 words
2015-04-02 15:16:09 --> ......processed 91/130 words
2015-04-02 15:16:09 --> ......processed 104/130 words
2015-04-02 15:16:09 --> ......processed 117/130 words
2015-04-02 15:16:09 --> ......processed 130/130 words
2015-04-02 15:16:09 --> ...updating 130 words into idxPHRASE19R ended
2015-04-02 15:16:09 --> ...updating reverse table idxPHRASE19R started
2015-04-02 15:16:09 --> ...updating reverse table idxPHRASE19R ended
2015-04-02 15:16:09 --> idxPHRASE19F normal wordtable flush ended
2015-04-02 15:16:09 --> 115 records took 0.2 seconds to complete.(34196 recs/min)
2015-04-02 15:16:09 --> Estimated runtime: 0.0 minutes
2015-04-02 15:16:09 --> idxPHRASE19F contains 130 words
2015-04-02 15:16:09 --> idxPHRASE19F is in consistent state
2015-04-02 15:16:09 --> Task #2 finished. [DONE]
2015-04-02 15:16:15 --> Task #3 submitted.
2015-04-02 15:16:20 --> Task #3 started.
2015-04-02 15:16:20 --> Virtual index: global is being updated for collection index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 25 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 2/25 words
2015-04-02 15:16:20 --> ......processed 4/25 words
2015-04-02 15:16:20 --> ......processed 6/25 words
2015-04-02 15:16:20 --> ......processed 8/25 words
2015-04-02 15:16:20 --> ......processed 10/25 words
2015-04-02 15:16:20 --> ......processed 12/25 words
2015-04-02 15:16:20 --> ......processed 14/25 words
2015-04-02 15:16:20 --> ......processed 16/25 words
2015-04-02 15:16:20 --> ......processed 18/25 words
2015-04-02 15:16:20 --> ......processed 20/25 words
2015-04-02 15:16:20 --> ......processed 22/25 words
2015-04-02 15:16:20 --> ......processed 24/25 words
2015-04-02 15:16:20 --> ...updating 25 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for abstract index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 81 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 8/81 words
2015-04-02 15:16:20 --> ......processed 16/81 words
2015-04-02 15:16:20 --> ......processed 24/81 words
2015-04-02 15:16:20 --> ......processed 32/81 words
2015-04-02 15:16:20 --> ......processed 40/81 words
2015-04-02 15:16:20 --> ......processed 48/81 words
2015-04-02 15:16:20 --> ......processed 56/81 words
2015-04-02 15:16:20 --> ......processed 64/81 words
2015-04-02 15:16:20 --> ......processed 72/81 words
2015-04-02 15:16:20 --> ......processed 80/81 words
2015-04-02 15:16:20 --> ...updating 81 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for keyword index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 20 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 2/20 words
2015-04-02 15:16:20 --> ......processed 4/20 words
2015-04-02 15:16:20 --> ......processed 6/20 words
2015-04-02 15:16:20 --> ......processed 8/20 words
2015-04-02 15:16:20 --> ......processed 10/20 words
2015-04-02 15:16:20 --> ......processed 12/20 words
2015-04-02 15:16:20 --> ......processed 14/20 words
2015-04-02 15:16:20 --> ......processed 16/20 words
2015-04-02 15:16:20 --> ......processed 18/20 words
2015-04-02 15:16:20 --> ......processed 20/20 words
2015-04-02 15:16:20 --> ...updating 20 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for reportnumber index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 138 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 13/138 words
2015-04-02 15:16:20 --> ......processed 26/138 words
2015-04-02 15:16:20 --> ......processed 39/138 words
2015-04-02 15:16:20 --> ......processed 52/138 words
2015-04-02 15:16:20 --> ......processed 65/138 words
2015-04-02 15:16:20 --> ......processed 78/138 words
2015-04-02 15:16:20 --> ......processed 91/138 words
2015-04-02 15:16:20 --> ......processed 104/138 words
2015-04-02 15:16:20 --> ......processed 117/138 words
2015-04-02 15:16:20 --> ......processed 130/138 words
2015-04-02 15:16:20 --> ...updating 138 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for title index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 130 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 13/130 words
2015-04-02 15:16:20 --> ......processed 26/130 words
2015-04-02 15:16:20 --> ......processed 39/130 words
2015-04-02 15:16:20 --> ......processed 52/130 words
2015-04-02 15:16:20 --> ......processed 65/130 words
2015-04-02 15:16:20 --> ......processed 78/130 words
2015-04-02 15:16:20 --> ......processed 91/130 words
2015-04-02 15:16:20 --> ......processed 104/130 words
2015-04-02 15:16:20 --> ......processed 117/130 words
2015-04-02 15:16:20 --> ......processed 130/130 words
2015-04-02 15:16:20 --> ...updating 130 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for year index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 28 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 2/28 words
2015-04-02 15:16:20 --> ......processed 4/28 words
2015-04-02 15:16:20 --> ......processed 6/28 words
2015-04-02 15:16:20 --> ......processed 8/28 words
2015-04-02 15:16:20 --> ......processed 10/28 words
2015-04-02 15:16:20 --> ......processed 12/28 words
2015-04-02 15:16:20 --> ......processed 14/28 words
2015-04-02 15:16:20 --> ......processed 16/28 words
2015-04-02 15:16:20 --> ......processed 18/28 words
2015-04-02 15:16:20 --> ......processed 20/28 words
2015-04-02 15:16:20 --> ......processed 22/28 words
2015-04-02 15:16:20 --> ......processed 24/28 words
2015-04-02 15:16:20 --> ......processed 26/28 words
2015-04-02 15:16:20 --> ......processed 28/28 words
2015-04-02 15:16:20 --> ...updating 28 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for journal index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 134 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 13/134 words
2015-04-02 15:16:20 --> ......processed 26/134 words
2015-04-02 15:16:20 --> ......processed 39/134 words
2015-04-02 15:16:20 --> ......processed 52/134 words
2015-04-02 15:16:20 --> ......processed 65/134 words
2015-04-02 15:16:20 --> ......processed 78/134 words
2015-04-02 15:16:20 --> ......processed 91/134 words
2015-04-02 15:16:20 --> ......processed 104/134 words
2015-04-02 15:16:20 --> ......processed 117/134 words
2015-04-02 15:16:20 --> ......processed 130/134 words
2015-04-02 15:16:20 --> ...updating 134 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for collaboration index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 8 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ...updating 8 words into idxPHRASE01R ended
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:20 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:20 --> Virtual index: global is being updated for affiliation index
2015-04-02 15:16:20 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:20 --> ...updating 63 words into idxPHRASE01F started
2015-04-02 15:16:20 --> ......processed 6/63 words
2015-04-02 15:16:20 --> ......processed 12/63 words
2015-04-02 15:16:20 --> ......processed 18/63 words
2015-04-02 15:16:20 --> ......processed 24/63 words
2015-04-02 15:16:20 --> ......processed 30/63 words
2015-04-02 15:16:21 --> ......processed 36/63 words
2015-04-02 15:16:21 --> ......processed 42/63 words
2015-04-02 15:16:21 --> ......processed 48/63 words
2015-04-02 15:16:21 --> ......processed 54/63 words
2015-04-02 15:16:21 --> ......processed 60/63 words
2015-04-02 15:16:21 --> ...updating 63 words into idxPHRASE01R ended
2015-04-02 15:16:21 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:21 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:21 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:21 --> Virtual index: global is being updated for exacttitle index
2015-04-02 15:16:21 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:21 --> ...updating 130 words into idxPHRASE01F started
2015-04-02 15:16:21 --> ......processed 13/130 words
2015-04-02 15:16:21 --> ......processed 26/130 words
2015-04-02 15:16:21 --> ......processed 39/130 words
2015-04-02 15:16:21 --> ......processed 52/130 words
2015-04-02 15:16:21 --> ......processed 65/130 words
2015-04-02 15:16:21 --> ......processed 78/130 words
2015-04-02 15:16:21 --> ......processed 91/130 words
2015-04-02 15:16:21 --> ......processed 104/130 words
2015-04-02 15:16:21 --> ......processed 117/130 words
2015-04-02 15:16:21 --> ......processed 130/130 words
2015-04-02 15:16:21 --> ...updating 130 words into idxPHRASE01R ended
2015-04-02 15:16:21 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:21 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:21 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:21 --> Virtual index: global is being updated for miscellaneous index
2015-04-02 15:16:21 --> idxPHRASE01F normal wordtable flush started
2015-04-02 15:16:21 --> ...updating 1901 words into idxPHRASE01F started
2015-04-02 15:16:21 --> ......processed 190/1901 words
2015-04-02 15:16:21 --> ......processed 380/1901 words
2015-04-02 15:16:21 --> ......processed 570/1901 words
2015-04-02 15:16:21 --> ......processed 760/1901 words
2015-04-02 15:16:21 --> ......processed 950/1901 words
2015-04-02 15:16:21 --> ......processed 1140/1901 words
2015-04-02 15:16:21 --> ......processed 1330/1901 words
2015-04-02 15:16:22 --> ......processed 1520/1901 words
2015-04-02 15:16:22 --> ......processed 1710/1901 words
2015-04-02 15:16:22 --> ......processed 1900/1901 words
2015-04-02 15:16:22 --> ...updating 1901 words into idxPHRASE01R ended
2015-04-02 15:16:22 --> ...updating reverse table idxPHRASE01R started
2015-04-02 15:16:22 --> ...updating reverse table idxPHRASE01R ended
2015-04-02 15:16:22 --> idxPHRASE01F normal wordtable flush ended
2015-04-02 15:16:22 --> Virtual index: global is being updated for collection index
2015-04-02 15:16:22 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:22 --> ...updating 18 words into idxPAIR01F started
2015-04-02 15:16:22 --> ......processed 1/18 words
2015-04-02 15:16:22 --> ......processed 2/18 words
2015-04-02 15:16:22 --> ......processed 3/18 words
2015-04-02 15:16:22 --> ......processed 4/18 words
2015-04-02 15:16:22 --> ......processed 5/18 words
2015-04-02 15:16:22 --> ......processed 6/18 words
2015-04-02 15:16:22 --> ......processed 7/18 words
2015-04-02 15:16:22 --> ......processed 8/18 words
2015-04-02 15:16:22 --> ......processed 9/18 words
2015-04-02 15:16:22 --> ......processed 10/18 words
2015-04-02 15:16:22 --> ......processed 11/18 words
2015-04-02 15:16:22 --> ......processed 12/18 words
2015-04-02 15:16:22 --> ......processed 13/18 words
2015-04-02 15:16:22 --> ......processed 14/18 words
2015-04-02 15:16:22 --> ......processed 15/18 words
2015-04-02 15:16:22 --> ......processed 16/18 words
2015-04-02 15:16:22 --> ......processed 17/18 words
2015-04-02 15:16:22 --> ......processed 18/18 words
2015-04-02 15:16:22 --> ...updating 18 words into idxPAIR01R ended
2015-04-02 15:16:22 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:22 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:22 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:22 --> Virtual index: global is being updated for abstract index
2015-04-02 15:16:22 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:22 --> ...updating 9923 words into idxPAIR01F started
2015-04-02 15:16:22 --> ......processed 992/9923 words
2015-04-02 15:16:23 --> ......processed 1984/9923 words
2015-04-02 15:16:23 --> ......processed 2976/9923 words
2015-04-02 15:16:23 --> ......processed 3968/9923 words
2015-04-02 15:16:24 --> ......processed 4960/9923 words
2015-04-02 15:16:24 --> ......processed 5952/9923 words
2015-04-02 15:16:24 --> ......processed 6944/9923 words
2015-04-02 15:16:25 --> ......processed 7936/9923 words
2015-04-02 15:16:25 --> ......processed 8928/9923 words
2015-04-02 15:16:25 --> ......processed 9920/9923 words
2015-04-02 15:16:25 --> ...updating 9923 words into idxPAIR01R ended
2015-04-02 15:16:25 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:25 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:25 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:25 --> Virtual index: global is being updated for keyword index
2015-04-02 15:16:25 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:25 --> ...updating 7 words into idxPAIR01F started
2015-04-02 15:16:25 --> ...updating 7 words into idxPAIR01R ended
2015-04-02 15:16:25 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:25 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:25 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:25 --> Virtual index: global is being updated for reportnumber index
2015-04-02 15:16:25 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:25 --> ...updating 245 words into idxPAIR01F started
2015-04-02 15:16:25 --> ......processed 24/245 words
2015-04-02 15:16:25 --> ......processed 48/245 words
2015-04-02 15:16:25 --> ......processed 72/245 words
2015-04-02 15:16:25 --> ......processed 96/245 words
2015-04-02 15:16:25 --> ......processed 120/245 words
2015-04-02 15:16:25 --> ......processed 144/245 words
2015-04-02 15:16:25 --> ......processed 168/245 words
2015-04-02 15:16:25 --> ......processed 192/245 words
2015-04-02 15:16:25 --> ......processed 216/245 words
2015-04-02 15:16:25 --> ......processed 240/245 words
2015-04-02 15:16:25 --> ...updating 245 words into idxPAIR01R ended
2015-04-02 15:16:25 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:25 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:25 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:25 --> Virtual index: global is being updated for title index
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:26 --> ...updating 858 words into idxPAIR01F started
2015-04-02 15:16:26 --> ......processed 85/858 words
2015-04-02 15:16:26 --> ......processed 170/858 words
2015-04-02 15:16:26 --> ......processed 255/858 words
2015-04-02 15:16:26 --> ......processed 340/858 words
2015-04-02 15:16:26 --> ......processed 425/858 words
2015-04-02 15:16:26 --> ......processed 510/858 words
2015-04-02 15:16:26 --> ......processed 595/858 words
2015-04-02 15:16:26 --> ......processed 680/858 words
2015-04-02 15:16:26 --> ......processed 765/858 words
2015-04-02 15:16:26 --> ......processed 850/858 words
2015-04-02 15:16:26 --> ...updating 858 words into idxPAIR01R ended
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:26 --> Virtual index: global is being updated for year index
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:26 --> ...updating 1 words into idxPAIR01F started
2015-04-02 15:16:26 --> ...updating 1 words into idxPAIR01R ended
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:26 --> Virtual index: global is being updated for journal index
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:26 --> ...updating 134 words into idxPAIR01F started
2015-04-02 15:16:26 --> ......processed 13/134 words
2015-04-02 15:16:26 --> ......processed 26/134 words
2015-04-02 15:16:26 --> ......processed 39/134 words
2015-04-02 15:16:26 --> ......processed 52/134 words
2015-04-02 15:16:26 --> ......processed 65/134 words
2015-04-02 15:16:26 --> ......processed 78/134 words
2015-04-02 15:16:26 --> ......processed 91/134 words
2015-04-02 15:16:26 --> ......processed 104/134 words
2015-04-02 15:16:26 --> ......processed 117/134 words
2015-04-02 15:16:26 --> ......processed 130/134 words
2015-04-02 15:16:26 --> ...updating 134 words into idxPAIR01R ended
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:26 --> Virtual index: global is being updated for collaboration index
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:26 --> ...updating 31 words into idxPAIR01F started
2015-04-02 15:16:26 --> ......processed 3/31 words
2015-04-02 15:16:26 --> ......processed 6/31 words
2015-04-02 15:16:26 --> ......processed 9/31 words
2015-04-02 15:16:26 --> ......processed 12/31 words
2015-04-02 15:16:26 --> ......processed 15/31 words
2015-04-02 15:16:26 --> ......processed 18/31 words
2015-04-02 15:16:26 --> ......processed 21/31 words
2015-04-02 15:16:26 --> ......processed 24/31 words
2015-04-02 15:16:26 --> ......processed 27/31 words
2015-04-02 15:16:26 --> ......processed 30/31 words
2015-04-02 15:16:26 --> ...updating 31 words into idxPAIR01R ended
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:26 --> Virtual index: global is being updated for affiliation index
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:26 --> ...updating 104 words into idxPAIR01F started
2015-04-02 15:16:26 --> ......processed 10/104 words
2015-04-02 15:16:26 --> ......processed 20/104 words
2015-04-02 15:16:26 --> ......processed 30/104 words
2015-04-02 15:16:26 --> ......processed 40/104 words
2015-04-02 15:16:26 --> ......processed 50/104 words
2015-04-02 15:16:26 --> ......processed 60/104 words
2015-04-02 15:16:26 --> ......processed 70/104 words
2015-04-02 15:16:26 --> ......processed 80/104 words
2015-04-02 15:16:26 --> ......processed 90/104 words
2015-04-02 15:16:26 --> ......processed 100/104 words
2015-04-02 15:16:26 --> ...updating 104 words into idxPAIR01R ended
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:26 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:26 --> Virtual index: global is being updated for exacttitle index
2015-04-02 15:16:26 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:26 --> ...updating 858 words into idxPAIR01F started
2015-04-02 15:16:26 --> ......processed 85/858 words
2015-04-02 15:16:26 --> ......processed 170/858 words
2015-04-02 15:16:26 --> ......processed 255/858 words
2015-04-02 15:16:26 --> ......processed 340/858 words
2015-04-02 15:16:26 --> ......processed 425/858 words
2015-04-02 15:16:26 --> ......processed 510/858 words
2015-04-02 15:16:27 --> ......processed 595/858 words
2015-04-02 15:16:27 --> ......processed 680/858 words
2015-04-02 15:16:27 --> ......processed 765/858 words
2015-04-02 15:16:27 --> ......processed 850/858 words
2015-04-02 15:16:27 --> ...updating 858 words into idxPAIR01R ended
2015-04-02 15:16:27 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:27 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:27 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:27 --> Virtual index: global is being updated for miscellaneous index
2015-04-02 15:16:27 --> idxPAIR01F normal wordtable flush started
2015-04-02 15:16:27 --> ...updating 2485 words into idxPAIR01F started
2015-04-02 15:16:27 --> ......processed 248/2485 words
2015-04-02 15:16:27 --> ......processed 496/2485 words
2015-04-02 15:16:27 --> ......processed 744/2485 words
2015-04-02 15:16:27 --> ......processed 992/2485 words
2015-04-02 15:16:27 --> ......processed 1240/2485 words
2015-04-02 15:16:27 --> ......processed 1488/2485 words
2015-04-02 15:16:27 --> ......processed 1736/2485 words
2015-04-02 15:16:27 --> ......processed 1984/2485 words
2015-04-02 15:16:27 --> ......processed 2232/2485 words
2015-04-02 15:16:27 --> ......processed 2480/2485 words
2015-04-02 15:16:27 --> ...updating 2485 words into idxPAIR01R ended
2015-04-02 15:16:27 --> ...updating reverse table idxPAIR01R started
2015-04-02 15:16:27 --> ...updating reverse table idxPAIR01R ended
2015-04-02 15:16:27 --> idxPAIR01F normal wordtable flush ended
2015-04-02 15:16:27 --> Virtual index: global is being updated for collection index
2015-04-02 15:16:27 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:27 --> ...updating 26 words into idxWORD01F started
2015-04-02 15:16:27 --> ......processed 2/26 words
2015-04-02 15:16:27 --> ......processed 4/26 words
2015-04-02 15:16:27 --> ......processed 6/26 words
2015-04-02 15:16:27 --> ......processed 8/26 words
2015-04-02 15:16:27 --> ......processed 10/26 words
2015-04-02 15:16:27 --> ......processed 12/26 words
2015-04-02 15:16:27 --> ......processed 14/26 words
2015-04-02 15:16:27 --> ......processed 16/26 words
2015-04-02 15:16:27 --> ......processed 18/26 words
2015-04-02 15:16:28 --> ......processed 20/26 words
2015-04-02 15:16:28 --> ......processed 22/26 words
2015-04-02 15:16:28 --> ......processed 24/26 words
2015-04-02 15:16:28 --> ......processed 26/26 words
2015-04-02 15:16:28 --> ...updating 26 words into idxWORD01R ended
2015-04-02 15:16:28 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:28 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:28 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:28 --> Virtual index: global is being updated for abstract index
2015-04-02 15:16:28 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:28 --> ...updating 4252 words into idxWORD01F started
2015-04-02 15:16:28 --> ......processed 425/4252 words
2015-04-02 15:16:28 --> ......processed 850/4252 words
2015-04-02 15:16:28 --> ......processed 1275/4252 words
2015-04-02 15:16:28 --> ......processed 1700/4252 words
2015-04-02 15:16:28 --> ......processed 2125/4252 words
2015-04-02 15:16:28 --> ......processed 2550/4252 words
2015-04-02 15:16:28 --> ......processed 2975/4252 words
2015-04-02 15:16:29 --> ......processed 3400/4252 words
2015-04-02 15:16:29 --> ......processed 3825/4252 words
2015-04-02 15:16:29 --> ......processed 4250/4252 words
2015-04-02 15:16:29 --> ...updating 4252 words into idxWORD01R ended
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:29 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:29 --> Virtual index: global is being updated for keyword index
2015-04-02 15:16:29 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:29 --> ...updating 28 words into idxWORD01F started
2015-04-02 15:16:29 --> ......processed 2/28 words
2015-04-02 15:16:29 --> ......processed 4/28 words
2015-04-02 15:16:29 --> ......processed 6/28 words
2015-04-02 15:16:29 --> ......processed 8/28 words
2015-04-02 15:16:29 --> ......processed 10/28 words
2015-04-02 15:16:29 --> ......processed 12/28 words
2015-04-02 15:16:29 --> ......processed 14/28 words
2015-04-02 15:16:29 --> ......processed 16/28 words
2015-04-02 15:16:29 --> ......processed 18/28 words
2015-04-02 15:16:29 --> ......processed 20/28 words
2015-04-02 15:16:29 --> ......processed 22/28 words
2015-04-02 15:16:29 --> ......processed 24/28 words
2015-04-02 15:16:29 --> ......processed 26/28 words
2015-04-02 15:16:29 --> ......processed 28/28 words
2015-04-02 15:16:29 --> ...updating 28 words into idxWORD01R ended
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:29 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:29 --> Virtual index: global is being updated for reportnumber index
2015-04-02 15:16:29 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:29 --> ...updating 374 words into idxWORD01F started
2015-04-02 15:16:29 --> ......processed 37/374 words
2015-04-02 15:16:29 --> ......processed 74/374 words
2015-04-02 15:16:29 --> ......processed 111/374 words
2015-04-02 15:16:29 --> ......processed 148/374 words
2015-04-02 15:16:29 --> ......processed 185/374 words
2015-04-02 15:16:29 --> ......processed 222/374 words
2015-04-02 15:16:29 --> ......processed 259/374 words
2015-04-02 15:16:29 --> ......processed 296/374 words
2015-04-02 15:16:29 --> ......processed 333/374 words
2015-04-02 15:16:29 --> ......processed 370/374 words
2015-04-02 15:16:29 --> ...updating 374 words into idxWORD01R ended
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:29 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:29 --> Virtual index: global is being updated for title index
2015-04-02 15:16:29 --> Error: Cannot put word β with sign 1 for recID 59.
2015-04-02 15:16:29 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:29 --> ...updating 707 words into idxWORD01F started
2015-04-02 15:16:29 --> ......processed 70/707 words
2015-04-02 15:16:29 --> ......processed 140/707 words
2015-04-02 15:16:29 --> ......processed 210/707 words
2015-04-02 15:16:29 --> ......processed 280/707 words
2015-04-02 15:16:29 --> ......processed 350/707 words
2015-04-02 15:16:29 --> ......processed 420/707 words
2015-04-02 15:16:29 --> ......processed 490/707 words
2015-04-02 15:16:29 --> ......processed 560/707 words
2015-04-02 15:16:29 --> ......processed 630/707 words
2015-04-02 15:16:29 --> ......processed 700/707 words
2015-04-02 15:16:29 --> ...updating 707 words into idxWORD01R ended
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:29 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:29 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:29 --> Virtual index: global is being updated for year index
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:30 --> ...updating 30 words into idxWORD01F started
2015-04-02 15:16:30 --> ......processed 3/30 words
2015-04-02 15:16:30 --> ......processed 6/30 words
2015-04-02 15:16:30 --> ......processed 9/30 words
2015-04-02 15:16:30 --> ......processed 12/30 words
2015-04-02 15:16:30 --> ......processed 15/30 words
2015-04-02 15:16:30 --> ......processed 18/30 words
2015-04-02 15:16:30 --> ......processed 21/30 words
2015-04-02 15:16:30 --> ......processed 24/30 words
2015-04-02 15:16:30 --> ......processed 27/30 words
2015-04-02 15:16:30 --> ......processed 30/30 words
2015-04-02 15:16:30 --> ...updating 30 words into idxWORD01R ended
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:30 --> Virtual index: global is being updated for journal index
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:30 --> ...updating 134 words into idxWORD01F started
2015-04-02 15:16:30 --> ......processed 13/134 words
2015-04-02 15:16:30 --> ......processed 26/134 words
2015-04-02 15:16:30 --> ......processed 39/134 words
2015-04-02 15:16:30 --> ......processed 52/134 words
2015-04-02 15:16:30 --> ......processed 65/134 words
2015-04-02 15:16:30 --> ......processed 78/134 words
2015-04-02 15:16:30 --> ......processed 91/134 words
2015-04-02 15:16:30 --> ......processed 104/134 words
2015-04-02 15:16:30 --> ......processed 117/134 words
2015-04-02 15:16:30 --> ......processed 130/134 words
2015-04-02 15:16:30 --> ...updating 134 words into idxWORD01R ended
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:30 --> Virtual index: global is being updated for collaboration index
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:30 --> ...updating 32 words into idxWORD01F started
2015-04-02 15:16:30 --> ......processed 3/32 words
2015-04-02 15:16:30 --> ......processed 6/32 words
2015-04-02 15:16:30 --> ......processed 9/32 words
2015-04-02 15:16:30 --> ......processed 12/32 words
2015-04-02 15:16:30 --> ......processed 15/32 words
2015-04-02 15:16:30 --> ......processed 18/32 words
2015-04-02 15:16:30 --> ......processed 21/32 words
2015-04-02 15:16:30 --> ......processed 24/32 words
2015-04-02 15:16:30 --> ......processed 27/32 words
2015-04-02 15:16:30 --> ......processed 30/32 words
2015-04-02 15:16:30 --> ...updating 32 words into idxWORD01R ended
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:30 --> Virtual index: global is being updated for affiliation index
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:30 --> ...updating 109 words into idxWORD01F started
2015-04-02 15:16:30 --> ......processed 10/109 words
2015-04-02 15:16:30 --> ......processed 20/109 words
2015-04-02 15:16:30 --> ......processed 30/109 words
2015-04-02 15:16:30 --> ......processed 40/109 words
2015-04-02 15:16:30 --> ......processed 50/109 words
2015-04-02 15:16:30 --> ......processed 60/109 words
2015-04-02 15:16:30 --> ......processed 70/109 words
2015-04-02 15:16:30 --> ......processed 80/109 words
2015-04-02 15:16:30 --> ......processed 90/109 words
2015-04-02 15:16:30 --> ......processed 100/109 words
2015-04-02 15:16:30 --> ...updating 109 words into idxWORD01R ended
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:30 --> Virtual index: global is being updated for exacttitle index
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:30 --> ...updating 707 words into idxWORD01F started
2015-04-02 15:16:30 --> ......processed 70/707 words
2015-04-02 15:16:30 --> ......processed 140/707 words
2015-04-02 15:16:30 --> ......processed 210/707 words
2015-04-02 15:16:30 --> ......processed 280/707 words
2015-04-02 15:16:30 --> ......processed 350/707 words
2015-04-02 15:16:30 --> ......processed 420/707 words
2015-04-02 15:16:30 --> ......processed 490/707 words
2015-04-02 15:16:30 --> ......processed 560/707 words
2015-04-02 15:16:30 --> ......processed 630/707 words
2015-04-02 15:16:30 --> ......processed 700/707 words
2015-04-02 15:16:30 --> ...updating 707 words into idxWORD01R ended
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:30 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:30 --> Virtual index: global is being updated for miscellaneous index
2015-04-02 15:16:30 --> idxWORD01F normal wordtable flush started
2015-04-02 15:16:30 --> ...updating 2782 words into idxWORD01F started
2015-04-02 15:16:30 --> ......processed 278/2782 words
2015-04-02 15:16:30 --> ......processed 556/2782 words
2015-04-02 15:16:31 --> ......processed 834/2782 words
2015-04-02 15:16:31 --> ......processed 1112/2782 words
2015-04-02 15:16:31 --> ......processed 1390/2782 words
2015-04-02 15:16:31 --> ......processed 1668/2782 words
2015-04-02 15:16:31 --> ......processed 1946/2782 words
2015-04-02 15:16:31 --> ......processed 2224/2782 words
2015-04-02 15:16:31 --> ......processed 2502/2782 words
2015-04-02 15:16:31 --> ......processed 2780/2782 words
2015-04-02 15:16:31 --> ...updating 2782 words into idxWORD01R ended
2015-04-02 15:16:31 --> ...updating reverse table idxWORD01R started
2015-04-02 15:16:31 --> ...updating reverse table idxWORD01R ended
2015-04-02 15:16:31 --> idxWORD01F normal wordtable flush ended
2015-04-02 15:16:31 --> Task #3 finished. [DONE]
2015-04-02 15:16:35 --> Task #4 submitted.
2015-04-02 15:16:39 --> Task #4 started.
2015-04-02 15:16:39 --> Task #4 finished. [RUNNING]
Content-Type: text/plain; charset="utf-8"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Subject: Exception (connections.py:36:defaulterrorhandler) at http://0.0.0.0:4000
From: [email protected]
To: [email protected]
Message-ID: <20150402131639.17293.5998@PCGS2X3160H65>
Date: Thu, 02 Apr 2015 15:16:39 +0200
User-Agent: Invenio 2.1.0.dev20150305 at http://0.0.0.0:4000

Hello:

This exception has already been seen 1 times
    last time it was seen: 2015-04-02 15:16:39
    last time it was notified: 2015-04-02 15:16:39

* 2015-04-02 15:16:39 -> ProgrammingError: (1146, "Table 'invenio2.format' doesn't exist") (connections.py:36:defaulterrorhandler)

** User details
No client information available

** Traceback details 

Traceback (most recent call last):
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 615, in task_init
    ret = _task_run(task_run_fnc)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 1191, in _task_run
    if callable(task_run_fnc) and task_run_fnc():
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py", line 337, in task_run_core
    last_updated = fetch_last_updated(fmt)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py", line 51, in fetch_last_updated
    row = run_sql(select_sql, (fmt.lower(), ))
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py", line 268, in run_sql
    rc = cur.execute(sql, param)
  File "/home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
    self.errorhandler(self, exc, value)
  File "/home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
ProgrammingError: (1146, "Table 'invenio2.format' doesn't exist")

** Stack frame details

Frame defaulterrorhandler in /home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/connections.py at line 36
-------------------------------------------------------------------------------
        33         connection.messages.append(error)
        34     del cursor
        35     del connection
---->   36     raise errorclass, errorvalue
        37 
        38 re_numeric_part = re.compile(r"^(\d+)")
        39 
-------------------------------------------------------------------------------
	          errorclass =  "<class '_mysql_exceptions.ProgrammingError'>"
	          errorvalue =  'ProgrammingError(1146, "Table \'invenio2.format\' doesn\'t exist")'
	               error =  '(<class \'_mysql_exceptions.ProgrammingError\'>, ProgrammingError(1146, "Table \'invenio2.format\' doesn\'t exist"))'

Frame execute in /home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/cursors.py at line 205
-------------------------------------------------------------------------------
       202             exc, value, tb = sys.exc_info()
       203             del tb
       204             self.messages.append((exc, value))
---->  205             self.errorhandler(self, exc, value)
       206         self._executed = query
       207         if not self._defer_warnings: self._warning_check()
       208         return r
-------------------------------------------------------------------------------
	                 exc =  "<class '_mysql_exceptions.ProgrammingError'>"
	                self =  '<MySQLdb.cursors.Cursor object at 0x7f1e2b28e390>'
	                args =  "('hb',)"
	                  db =  '<weakproxy at 0x7f1e34e00940 to Connection at 0x515bc10>'
	               value =  'ProgrammingError(1146, "Table \'invenio2.format\' doesn\'t exist")'
	                item =  "'hb'"
	                   r =  'None'
	               query =  '"SELECT last_updated FROM format WHERE code = \'hb\'"'

Frame run_sql in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py at line 284
-------------------------------------------------------------------------------
       281             gc.enable()
       282         except (OperationalError, InterfaceError):
       283             # unexpected disconnect, bad malloc error, etc
---->  284             raise
       285 
       286     if string.upper(string.split(sql)[0]) in \
       287        ("SELECT", "SHOW", "DESC", "DESCRIBE"):
-------------------------------------------------------------------------------
	                 cur =  '<MySQLdb.cursors.Cursor object at 0x7f1e2b28e390>'
	           with_desc =  'False'
	              dbhost =  "u'localhost'"
	                  db =  "<_mysql.connection open to 'localhost' at 515bc10>"
	               param =  "('hb',)"
	                   n =  '0'
	          connection =  'None'
	                 sql =  "'SELECT last_updated FROM format WHERE code = %s'"
	           with_dict =  'False'
	        run_on_slave =  'False'

Frame fetch_last_updated in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py at line 51
-------------------------------------------------------------------------------
        48 
        49 def fetch_last_updated(fmt):
        50     select_sql = "SELECT last_updated FROM format WHERE code = %s"
---->   51     row = run_sql(select_sql, (fmt.lower(), ))
        52 
        53     # Fallback in case we receive None instead of a valid date
        54     last_date = row[0][0] or datetime(year=1900, month=1, day=1)
-------------------------------------------------------------------------------
	                 fmt =  "'HB'"
	          select_sql =  "'SELECT last_updated FROM format WHERE code = %s'"

Frame task_run_core in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py at line 337
-------------------------------------------------------------------------------
       334     """
       335     fmts = task_get_option('format', 'HB,RECJSON')
       336     for fmt in fmts.split(','):
---->  337         last_updated = fetch_last_updated(fmt)
       338         write_message("last stored run date is %s" % last_updated)
       339 
       340         recids = intbitset()
-------------------------------------------------------------------------------
	                 fmt =  "'HB'"
	                fmts =  "'HB'"

Frame _task_run in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py at line 1230
-------------------------------------------------------------------------------
      1227             ## we are done:
      1228             write_message("Task #%d finished. [%s]" % (_TASK_PARAMS['task_id'], task_status))
      1229         ## Removing the pid
----> 1230         os.remove(pidfile_name)
      1231 
      1232     #Lets call the post-process tasklets
      1233     if task_get_task_param("post-process"):
-------------------------------------------------------------------------------
	 CFG_BIBTASK_RUN_DIR =  "'/home/jnotarst/.virtualenvs/invenio2/var/invenio.base-instance/run'"
	           _TASKLETS =  '<invenio.utils.datastructures.LazyDict object at 0x7f1e2b28ea50>'
	           sleeptime =  "''"
	            time_now =  'datetime.datetime(2015, 4, 2, 15, 16, 39, 465868)'
	        pidfile_name =  "'/home/jnotarst/.virtualenvs/invenio2/var/invenio.base-instance/run/bibsched_task_4.pid'"
	                host =  "''"
	        task_run_fnc =  '<function task_run_core at 0x7f1e2b2f6a28>'
	         task_status =  "'RUNNING'"
	             pidfile =  "<closed file '/home/jnotarst/.virtualenvs/invenio2/var/invenio.base-instance/run/bibsched_task_4.pid', mode 'w' at 0x7f1e2b395e40>"

Frame task_init in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py at line 624
-------------------------------------------------------------------------------
       621                 # an error traceback
       622                 if isinstance(e, SystemExit) and e.code == 0:
       623                     raise
---->  624                 register_exception(alert_admin=True)
       625                 write_message("Unexpected error occurred: %s." % e, sys.stderr)
       626                 write_message("Traceback is:", sys.stderr)
       627                 write_messages(''.join(traceback.format_tb(sys.exc_info()[2])), sys.stderr)
-------------------------------------------------------------------------------
	  configure_warnings =  '<function configure_warnings at 0x7f1e3d44a758>'
	task_submit_check_options_fnc =  '<function task_submit_check_options at 0x7f1e2b2f6b18>'
	                   e =  'ProgrammingError(1146, "Table \'invenio2.format\' doesn\'t exist")'
	             version =  "'$Id$'"
	 help_specific_usage =  "'  -o,  --formats         \\t Specify output format/s (default HB)\\n  -n,  --noprocess      \\t Count records to be formatted (no processing done)\\nReformatting options:\\n  -a,  --all            \\t Force reformatting all records\\n  -c,  --collection     \\t Force reformatting records by collection\\n  -f,  --field          \\t Force reformatting records by field\\n  -p,  --pattern        \\t Force reformatting records by pattern\\n  -i,  --id             \\t Force reformatting records by r [...]
	     to_be_submitted =  'False'
	                argv =  "['/home/jnotarst/.virtualenvs/invenio2/bin/bibreformat', '-u', 'admin', '-o', 'HB']"
	     specific_params =  "('ac:f:p:lo:nm:i:', ['all', 'collection=', 'matching=', 'field=', 'pattern=', 'format=', 'noprocess', 'id=', 'no-missing'])"
	        task_run_fnc =  '<function task_run_core at 0x7f1e2b2f6a28>'
	              params =  "{'user': 'admin'}"
	task_submit_elaborate_specific_parameter_fnc =  '<function task_submit_elaborate_specific_parameter at 0x7f1e2b2f6b90>'
	           task_name =  "'bibreformat'"
	task_stop_helper_fnc =  'None'
	authorization_action =  "'runbibformat'"
	   authorization_msg =  "'BibReformat Task Submission'"
	         description =  '"\\nBibReformat formats the records and saves the produced outputs for\\nlater retrieval.\\n\\nBibReformat is usually run periodically via BibSched in order to (1)\\nformat new records in the database and to (2) reformat records for\\nwhich the meta data has been modified.\\n\\nBibReformat has to be run manually when (3) format config files have\\nbeen modified, in order to see the changes in the web interface.\\n\\nAlthough it is not necessary to run BibReformat to display formatted\\nrecords  [...]






Best regards
--
Atlantis Institute of Fictive Science <http://0.0.0.0:4000>
Need human intervention?  Contact <[email protected]>


-------------------------------------------------------------------------------
2015-04-02 15:16:39 --> 
Traceback (most recent call last):
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 615, in task_init
    ret = _task_run(task_run_fnc)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 1191, in _task_run
    if callable(task_run_fnc) and task_run_fnc():
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py", line 337, in task_run_core
    last_updated = fetch_last_updated(fmt)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py", line 51, in fetch_last_updated
    row = run_sql(select_sql, (fmt.lower(), ))
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py", line 268, in run_sql
    rc = cur.execute(sql, param)
  File "/home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
    self.errorhandler(self, exc, value)
  File "/home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
ProgrammingError: (1146, "Table 'invenio2.format' doesn't exist")
2015-04-02 15:16:39 --> Unexpected error occurred: (1146, "Table 'invenio2.format' doesn't exist").
2015-04-02 15:16:39 --> Traceback is:
2015-04-02 15:16:39 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 615, in task_init
2015-04-02 15:16:39 -->     ret = _task_run(task_run_fnc)
2015-04-02 15:16:39 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 1191, in _task_run
2015-04-02 15:16:39 -->     if callable(task_run_fnc) and task_run_fnc():
2015-04-02 15:16:39 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py", line 337, in task_run_core
2015-04-02 15:16:39 -->     last_updated = fetch_last_updated(fmt)
2015-04-02 15:16:39 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibformat/bibreformat.py", line 51, in fetch_last_updated
2015-04-02 15:16:39 -->     row = run_sql(select_sql, (fmt.lower(), ))
2015-04-02 15:16:39 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/dbquery_mysql.py", line 268, in run_sql
2015-04-02 15:16:39 -->     rc = cur.execute(sql, param)
2015-04-02 15:16:39 -->   File "/home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
2015-04-02 15:16:39 -->     self.errorhandler(self, exc, value)
2015-04-02 15:16:39 -->   File "/home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2015-04-02 15:16:39 -->     raise errorclass, errorvalue
2015-04-02 15:16:39 --> Exiting.
2015-04-02 15:16:43 --> Task #5 submitted.
2015-04-02 15:16:47 --> Task #5 started.
2015-04-02 15:16:47 --> Running rank method: citation.
2015-04-02 15:16:47 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py:393: UserWarning: Deprecated perform_request_search({'op1': '', 'op2': '', 'cc': 'Atlantis Institute of Fictive Science', 'd2': '', 'verbose': 0, 'jrec': 0, 'ln': 'en', 'selected_external_collections_infos': None, 'm1': '', 'm3': '', 'm2': '', 'dt': '', 'p2': '', 'p3': '', 'p1': '', 'f': '', 'p': '', 'recid': -1, 'aas': 0, 'em': '', 'f1': '', 'f2': '', 'f3': '', 'uid': 0, 'datetext2': '', 'datetext1': '', 'ec': None, 'ap': 0, 'tab': '', 'id': -1, 'd2y': 0, 'sysnb': '', 'req': None, 'sysno': '', 'rg': None, 'd2m': 0, 'rm': '', 'd1': '', 'd2d': 0, 'wl': 0, 'sc': 0, '_': <function unicode_gettext_wrapper at 0x7f83063a7050>, 'c': ['Articles & Preprints', 'Atlantis Institute of Fictive Science'], 'of': 'id', 'sp': '', 'd1y': 0, 'd1d': 0, 'so': 'a', 'recidb': -1, 'action': '', 'd1m': 0, 'ot': '', 'idb': -1, 'sf': ''}).
  recIDs = perform_request_search(c=l_of_colls)

2015-04-02 15:16:47 --> bibrank: 1900-01-01 00:00:00
2015-04-02 15:16:47 --> bibindex: 2015-04-02 15:14:54
2015-04-02 15:16:47 --> [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, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 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, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 122, 123, 124, 125, 126, 127, 128, 129, 130, 131, 132, 133, 134, 135, 136, 137, 138, 139, 140, 141, 142] records to update
2015-04-02 15:16:47 --> Processing chunk #142 to #1
2015-04-02 15:16:47 --> get cit.inf done 0 of 142
2015-04-02 15:16:47 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/docextract/record.py:80: UserWarning: Deprecated get_record(142).
  record = get_record_original(recid)

2015-04-02 15:16:47 --> Error retrieving the blob for recid 142
Traceback (most recent call last):
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/modules/records/api.py", line 103, in get_blob
    or_(Bibfmt.kind == 'master', Bibfmt.format == 'xm')).one()
  File "/home/jnotarst/.virtualenvs/invenio2/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2404, in one
    raise orm_exc.NoResultFound("No row was found for one()")
NoResultFound: No row was found for one()
2015-04-02 15:16:47 --> Task #5 finished. [RUNNING]
Content-Type: text/plain; charset="utf-8"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Subject: Exception (__init__.py:577:get_record) at http://0.0.0.0:4000
From: [email protected]
To: [email protected]
Message-ID: <20150402131647.17315.22245@PCGS2X3160H65>
Date: Thu, 02 Apr 2015 15:16:47 +0200
User-Agent: Invenio 2.1.0.dev20150305 at http://0.0.0.0:4000

Hello:

This exception has already been seen 1 times
    last time it was seen: 2015-04-02 15:16:47
    last time it was notified: 2015-04-02 15:16:47

* 2015-04-02 15:16:47 -> AttributeError: 'NoneType' object has no attribute 'legacy_create_recstruct' (__init__.py:577:get_record)

** User details
No client information available

** Traceback details 

Traceback (most recent call last):
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 615, in task_init
    ret = _task_run(task_run_fnc)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 1191, in _task_run
    if callable(task_run_fnc) and task_run_fnc():
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/cli.py", line 162, in task_run_core
    func_object(key)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 452, in citation
    return bibrank_engine(run)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 365, in bibrank_engine
    func_object(rank_method_code, cfg_name, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 71, in citation_exec
    dic, index_update_time = get_citation_weight(rank_method_code, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 146, in get_citation_weight
    weights = process_and_store(updated_recids, config, chunk_size)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 182, in process_and_store
    cites, refs = process_chunk(chunk, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 216, in process_chunk
    citation_informations = get_citation_informations(recids, tags, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 517, in get_citation_informations
    record = get_record(recid)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/docextract/record.py", line 80, in get_record
    record = get_record_original(recid)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/search_engine/__init__.py", line 577, in get_record
    return api.get_record(recid).legacy_create_recstruct()
AttributeError: 'NoneType' object has no attribute 'legacy_create_recstruct'

** Stack frame details

Frame get_record in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/search_engine/__init__.py at line 577
-------------------------------------------------------------------------------
       574     warnings.warn('Deprecated get_record({}).'.format(str(recid)),
       575                   stacklevel=2)
       576     from invenio.modules.records import api
---->  577     return api.get_record(recid).legacy_create_recstruct()
       578 
       579 
       580 def print_record(recID, format='hb', ot='', ln=CFG_SITE_LANG, decompress=zlib.decompress,
-------------------------------------------------------------------------------
	                 api =  "<module 'invenio.modules.records.api' from '/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/modules/records/api.pyc'>"
	               recid =  '142'
	            warnings =  "<module 'warnings' from '/home/jnotarst/.virtualenvs/invenio2/lib/python2.7/warnings.pyc'>"

Frame get_record in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/docextract/record.py at line 80
-------------------------------------------------------------------------------
        77 
        78 def get_record(recid):
        79     """Fetch record from the database and loads it into a bibrecord"""
---->   80     record = get_record_original(recid)
        81     return convert_record(record)
        82 
        83 
-------------------------------------------------------------------------------
	               recid =  '142'

Frame get_citation_informations in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py at line 517
-------------------------------------------------------------------------------
       514             write_message(mesg)
       515             task_update_progress(mesg)
       516 
---->  517         record = get_record(recid)
       518         records_info['record_id'][recid] = [unicode(recid)]
       519 
       520         function = config.get("rank_method", "function")
-------------------------------------------------------------------------------
	  fetch_catchup_info =  'True'
	                tags =  '{\'doi\': [], \'isbn\': [u\'020__a\'], \'publication\': None, \'record_pri_number\': \'037__a\', \'publication_format\': \'"p v (y) c"\', \'refs_report_number\': \'999C5r\', \'record_add_number\': \'088__a\', \'refs_isbn\': \'999C5i\', \'refs_doi\': \'999C5a\', \'refs_record_id\': \'999C50\', \'refs_journal\': \'999C5s\'}'
	              config =  '<ConfigParser.ConfigParser instance at 0x7f8306391e18>'
	        records_info =  "{'doi': {}, 'isbn': {}, 'report-numbers': {}, 'record_id': {}, 'hdl': {}, 'journals': {}}"
	               recid =  '142'
	     references_info =  "{'doi': {}, 'isbn': {}, 'report-numbers': {}, 'record_id': {}, 'hdl': {}, 'journals': {}}"
	          begin_time =  '17196784.79'
	                done =  '0'
	                mesg =  "'get cit.inf done 0 of 142'"
	          recid_list =  '[142, 141, 140, 139, 138, 137, 136, 135, 134, 133, 132, 131, 130, 129, 128, 127, 126, 125, 124, 123, 122, 121, 120, 119, 118, 117, 116, 115, 114, 113, 112, 111, 110, 109, 108, 107, 106, 105, 104, 103, 102, 101, 100, 99, 98, 97, 96, 95, 94, 93, 92, 91, 90, 89, 88, 87, 86, 85, 84, 83, 82, 81, 80, 79, 78, 77, 76, 75, 74, 73, 72, 71, 70, 69, 68, 67, 66, 65, 64, 63, 62, 61, 60, 59, 58, 57, 56, 55, 54, 53, 52, 51, 50, 49, 48, 47, 46, 45, 44, 43, 42, 41, 40, 39, 38, 37, 36, 35, 34, 33, 32, 31, 30, 29, [...]

Frame process_chunk in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py at line 216
-------------------------------------------------------------------------------
       213     # call the procedure that does the hard work by reading fields of
       214     # citations and references in the updated_recid's (but nothing else)!
       215     write_message("Entering get_citation_informations", verbose=9)
---->  216     citation_informations = get_citation_informations(recids, tags, config)
       217 
       218     write_message("Entering ref_analyzer", verbose=9)
       219     # call the analyser that uses the citation_informations to really
-------------------------------------------------------------------------------
	              config =  '<ConfigParser.ConfigParser instance at 0x7f8306391e18>'
	              recids =  '[142, 141, 140, 139, 138, 137, 136, 135, 134, 133, 132, 131, 130, 129, 128, 127, 126, 125, 124, 123, 122, 121, 120, 119, 118, 117, 116, 115, 114, 113, 112, 111, 110, 109, 108, 107, 106, 105, 104, 103, 102, 101, 100, 99, 98, 97, 96, 95, 94, 93, 92, 91, 90, 89, 88, 87, 86, 85, 84, 83, 82, 81, 80, 79, 78, 77, 76, 75, 74, 73, 72, 71, 70, 69, 68, 67, 66, 65, 64, 63, 62, 61, 60, 59, 58, 57, 56, 55, 54, 53, 52, 51, 50, 49, 48, 47, 46, 45, 44, 43, 42, 41, 40, 39, 38, 37, 36, 35, 34, 33, 32, 31, 30, 29, [...]
	                tags =  '{\'doi\': [], \'isbn\': [u\'020__a\'], \'publication\': None, \'record_pri_number\': \'037__a\', \'publication_format\': \'"p v (y) c"\', \'refs_report_number\': \'999C5r\', \'record_add_number\': \'088__a\', \'refs_isbn\': \'999C5i\', \'refs_doi\': \'999C5a\', \'refs_record_id\': \'999C50\', \'refs_journal\': \'999C5s\'}'

Frame process_and_store in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py at line 182
-------------------------------------------------------------------------------
       179 
       180         write_message("Processing chunk #%s to #%s" % (chunk[0], chunk[-1]))
       181         # The core work
---->  182         cites, refs = process_chunk(chunk, config)
       183         # Check that we haven't lost too many citations
       184         cites_diff = compute_dicts_diff(chunk, refs, cites)
       185         write_message("Citations balance %s" % cites_diff)
-------------------------------------------------------------------------------
	            function =  "'citation'"
	              recids =  '[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, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 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, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 1 [...]
	               chunk =  '[142, 141, 140, 139, 138, 137, 136, 135, 134, 133, 132, 131, 130, 129, 128, 127, 126, 125, 124, 123, 122, 121, 120, 119, 118, 117, 116, 115, 114, 113, 112, 111, 110, 109, 108, 107, 106, 105, 104, 103, 102, 101, 100, 99, 98, 97, 96, 95, 94, 93, 92, 91, 90, 89, 88, 87, 86, 85, 84, 83, 82, 81, 80, 79, 78, 77, 76, 75, 74, 73, 72, 71, 70, 69, 68, 67, 66, 65, 64, 63, 62, 61, 60, 59, 58, 57, 56, 55, 54, 53, 52, 51, 50, 49, 48, 47, 46, 45, 44, 43, 42, 41, 40, 39, 38, 37, 36, 35, 34, 33, 32, 31, 30, 29, [...]
	 citation_loss_limit =  '50'
	            modified =  'False'
	         recids_iter =  '<listiterator object at 0x7f83063a16d0>'
	          chunk_size =  '25000'
	              config =  '<ConfigParser.ConfigParser instance at 0x7f8306391e18>'

Frame get_citation_weight in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py at line 146
-------------------------------------------------------------------------------
       143         except ConfigParser.NoOptionError:
       144             config.set(function, 'collections', None)
       145         # Process fully the updated records
---->  146         weights = process_and_store(updated_recids, config, chunk_size)
       147         end_time = time.time()
       148         write_message("Total time of get_citation_weight(): %.2f sec" %
       149                                                       (end_time - begin_time))
-------------------------------------------------------------------------------
	            function =  "'citation'"
	  str_updated_recids =  "'[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, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 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, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121,  [...]
	 bibrank_update_time =  "'1900-01-01 00:00:00'"
	          chunk_size =  '25000'
	   index_update_time =  "'2015-04-02 15:14:54'"
	    rank_method_code =  "'citation'"
	          begin_time =  '1427980607.266413'
	               quick =  'True'
	              config =  '<ConfigParser.ConfigParser instance at 0x7f8306391e18>'
	      updated_recids =  '[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, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 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, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 1 [...]

Frame citation_exec in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py at line 71
-------------------------------------------------------------------------------
        68         num = task_get_option("num")
        69         print_missing(num)
        70     else:
---->   71         dic, index_update_time = get_citation_weight(rank_method_code, config)
        72         if dic:
        73             if task_get_option("id") or task_get_option("collection") or \
        74                task_get_option("modified"):
-------------------------------------------------------------------------------
	    rank_method_code =  "'citation'"
	              config =  '<ConfigParser.ConfigParser instance at 0x7f8306391e18>'
	                name =  "'citation'"

Frame bibrank_engine in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py at line 365
-------------------------------------------------------------------------------
       362             del_recids(cfg_short, options["recid_range"])
       363         elif task_get_option("cmd") == "add":
       364             func_object = globals().get(cfg_function)
---->  365             func_object(rank_method_code, cfg_name, config)
       366         elif task_get_option("cmd") == "stat":
       367             rank_method_code_statistics(rank_method_code)
       368         elif task_get_option("cmd") == "check":
-------------------------------------------------------------------------------
	    rank_method_code =  "'citation'"
	                 run =  "'citation'"
	           cfg_short =  "'citation'"
	         func_object =  '<function citation_exec at 0x7f8306540050>'
	            cfg_name =  "'citation'"
	         startCreate =  '1427980607.137648'
	              config =  '<ConfigParser.ConfigParser instance at 0x7f8306391e18>'
	        cfg_function =  "'citation_exec'"
	 cfg_repair_function =  "'citation_repair_exec'"

Frame citation in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py at line 452
-------------------------------------------------------------------------------
       449     write_message("Time used: %d second(s)." % timeused, verbose=9)
       450 
       451 def citation(run):
---->  452     return bibrank_engine(run)
       453 
       454 
       455 # Hack to put index based sorting here, but this is very similar to tag
-------------------------------------------------------------------------------
	                 run =  "'citation'"

Frame task_run_core in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/cli.py at line 162
-------------------------------------------------------------------------------
       159         cfg_function = config.get("rank_method", "function")
       160         func_object = globals().get(cfg_function)
       161         if func_object:
---->  162             func_object(key)
       163         else:
       164             write_message("Cannot run method '%s', no function to call"
       165                 % key)
-------------------------------------------------------------------------------
	                name =  "('selfcites',)"
	         func_object =  '<function citation at 0x7f8306540b90>'
	            filename =  "'/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/modules/ranker/rankext/configuration/citation.cfg'"
	                 key =  "'citation'"
	              config =  '<ConfigParser.ConfigParser instance at 0x7f8306391a70>'
	        cfg_function =  "'citation'"

Frame _task_run in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py at line 1230
-------------------------------------------------------------------------------
      1227             ## we are done:
      1228             write_message("Task #%d finished. [%s]" % (_TASK_PARAMS['task_id'], task_status))
      1229         ## Removing the pid
----> 1230         os.remove(pidfile_name)
      1231 
      1232     #Lets call the post-process tasklets
      1233     if task_get_task_param("post-process"):
-------------------------------------------------------------------------------
	 CFG_BIBTASK_RUN_DIR =  "'/home/jnotarst/.virtualenvs/invenio2/var/invenio.base-instance/run'"
	           _TASKLETS =  '<invenio.utils.datastructures.LazyDict object at 0x7f83063a10d0>'
	           sleeptime =  "''"
	            time_now =  'datetime.datetime(2015, 4, 2, 15, 16, 47, 110451)'
	        pidfile_name =  "'/home/jnotarst/.virtualenvs/invenio2/var/invenio.base-instance/run/bibsched_task_5.pid'"
	                host =  "''"
	        task_run_fnc =  '<function task_run_core at 0x7f8306396140>'
	         task_status =  "'RUNNING'"
	             pidfile =  "<closed file '/home/jnotarst/.virtualenvs/invenio2/var/invenio.base-instance/run/bibsched_task_5.pid', mode 'w' at 0x7f8306401ae0>"

Frame task_init in /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py at line 624
-------------------------------------------------------------------------------
       621                 # an error traceback
       622                 if isinstance(e, SystemExit) and e.code == 0:
       623                     raise
---->  624                 register_exception(alert_admin=True)
       625                 write_message("Unexpected error occurred: %s." % e, sys.stderr)
       626                 write_message("Traceback is:", sys.stderr)
       627                 write_messages(''.join(traceback.format_tb(sys.exc_info()[2])), sys.stderr)
-------------------------------------------------------------------------------
	  configure_warnings =  '<function configure_warnings at 0x7f8317b22758>'
	task_submit_check_options_fnc =  'None'
	                   e =  'AttributeError("\'NoneType\' object has no attribute \'legacy_create_recstruct\'",)'
	             version =  "'$Id$'"
	 help_specific_usage =  "'Ranking options:\\n -w, --run=r1[,r2]         runs each rank method in the order given\\n\\n -c, --collection=c1[,c2]  select according to collection\\n -i, --id=low[-high]       select according to doc recID\\n -m, --modified=from[,to]  select according to modification date\\n -l, --lastupdate          select according to last update\\n\\n -a, --add                 add or update words for selected records\\n -d, --del                 delete words for selected records\\n -S, --stat             [...]
	     to_be_submitted =  'False'
	                argv =  "['/home/jnotarst/.virtualenvs/invenio2/bin/bibrank', '-u', 'admin']"
	     specific_params =  "('AE:ladSi:m:c:kUrRM:f:w:', ['author-citations', 'print-extcites=', 'lastupdate', 'add', 'del', 'repair', 'maxmem', 'flush', 'stat', 'rebalance', 'id=', 'collection=', 'check', 'modified=', 'update', 'run='])"
	        task_run_fnc =  '<function task_run_core at 0x7f8306396140>'
	              params =  "{'user': 'admin'}"
	task_submit_elaborate_specific_parameter_fnc =  '<function task_submit_elaborate_specific_parameter at 0x7f8306396230>'
	           task_name =  "'bibrank'"
	task_stop_helper_fnc =  'None'
	authorization_action =  "'runbibrank'"
	   authorization_msg =  "'BibRank Task Submission'"
	         description =  '"Ranking examples:\\n       bibrank -wjif -a --id=0-30000,30001-860000 --verbose=9\\n       bibrank -wjif -d --modified=\'2002-10-27 13:57:26\'\\n       bibrank -wjif --rebalance --collection=Articles\\n       bibrank -wsbr -a -i 234-250,293,300-500 -u admin\\n       bibrank -u admin -w citation -E 10\\n       bibrank -u admin -w citation -A\\n"'






Best regards
--
Atlantis Institute of Fictive Science <http://0.0.0.0:4000>
Need human intervention?  Contact <[email protected]>


-------------------------------------------------------------------------------
2015-04-02 15:16:47 --> 
Traceback (most recent call last):
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 615, in task_init
    ret = _task_run(task_run_fnc)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 1191, in _task_run
    if callable(task_run_fnc) and task_run_fnc():
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/cli.py", line 162, in task_run_core
    func_object(key)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 452, in citation
    return bibrank_engine(run)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 365, in bibrank_engine
    func_object(rank_method_code, cfg_name, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 71, in citation_exec
    dic, index_update_time = get_citation_weight(rank_method_code, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 146, in get_citation_weight
    weights = process_and_store(updated_recids, config, chunk_size)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 182, in process_and_store
    cites, refs = process_chunk(chunk, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 216, in process_chunk
    citation_informations = get_citation_informations(recids, tags, config)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 517, in get_citation_informations
    record = get_record(recid)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/docextract/record.py", line 80, in get_record
    record = get_record_original(recid)
  File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/search_engine/__init__.py", line 577, in get_record
    return api.get_record(recid).legacy_create_recstruct()
AttributeError: 'NoneType' object has no attribute 'legacy_create_recstruct'
2015-04-02 15:16:47 --> Unexpected error occurred: 'NoneType' object has no attribute 'legacy_create_recstruct'.
2015-04-02 15:16:47 --> Traceback is:
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 615, in task_init
2015-04-02 15:16:47 -->     ret = _task_run(task_run_fnc)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsched/bibtask.py", line 1191, in _task_run
2015-04-02 15:16:47 -->     if callable(task_run_fnc) and task_run_fnc():
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/cli.py", line 162, in task_run_core
2015-04-02 15:16:47 -->     func_object(key)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 452, in citation
2015-04-02 15:16:47 -->     return bibrank_engine(run)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 365, in bibrank_engine
2015-04-02 15:16:47 -->     func_object(rank_method_code, cfg_name, config)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/tag_based_indexer.py", line 71, in citation_exec
2015-04-02 15:16:47 -->     dic, index_update_time = get_citation_weight(rank_method_code, config)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 146, in get_citation_weight
2015-04-02 15:16:47 -->     weights = process_and_store(updated_recids, config, chunk_size)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 182, in process_and_store
2015-04-02 15:16:47 -->     cites, refs = process_chunk(chunk, config)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 216, in process_chunk
2015-04-02 15:16:47 -->     citation_informations = get_citation_informations(recids, tags, config)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibrank/citation_indexer.py", line 517, in get_citation_informations
2015-04-02 15:16:47 -->     record = get_record(recid)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/docextract/record.py", line 80, in get_record
2015-04-02 15:16:47 -->     record = get_record_original(recid)
2015-04-02 15:16:47 -->   File "/home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/search_engine/__init__.py", line 577, in get_record
2015-04-02 15:16:47 -->     return api.get_record(recid).legacy_create_recstruct()
2015-04-02 15:16:47 --> Exiting.
2015-04-02 15:16:51 --> Task #6 submitted.
2015-04-02 15:16:54 --> Task #6 started.
2015-04-02 15:16:54 --> bibsort starting..
2015-04-02 15:16:54 --> Running rebalancing for methods: ['most cited', 'latest first', 'report number', 'author', 'title']
2015-04-02 15:16:54 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibsort/engine.py:91: UserWarning: Deprecated search_pattern(p=980__:"DELETED", f=None, m=None) = intbitset([]).
  deleted = search_pattern(p='980__:"DELETED"')

2015-04-02 15:16:54 --> Starting sorting the data for MOST CITED method ... 
2015-04-02 15:16:54 --> POSSIBLE ERROR: The sorting method --most cited-- has no data!
2015-04-02 15:16:54 --> Done.
2015-04-02 15:16:54 --> Starting sorting the data for LATEST FIRST method ... 
2015-04-02 15:16:54 --> Done.
2015-04-02 15:16:54 --> Starting sorting the data for REPORT NUMBER method ... 
2015-04-02 15:16:54 --> Done.
2015-04-02 15:16:54 --> Starting sorting the data for AUTHOR method ... 
2015-04-02 15:16:54 --> Done.
2015-04-02 15:16:54 --> Starting sorting the data for TITLE method ... 
2015-04-02 15:16:54 --> Setting locale to %s is not working.. ignoring locale
2015-04-02 15:16:54 --> Done.
2015-04-02 15:16:54 --> bibsort exiting..
2015-04-02 15:16:54 --> Task #6 finished. [DONE]
2015-04-02 15:16:58 --> Task #7 submitted.
2015-04-02 15:17:02 --> Task #7 started.
2015-04-02 15:17:02 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/oairepository/updater.py:148: UserWarning: Deprecated perform_request_search({'op1': '', 'op2': '', 'cc': 'Atlantis Institute of Fictive Science', 'd2': '', 'verbose': 0, 'jrec': 0, 'ln': 'en', 'selected_external_collections_infos': None, 'm1': 'a', 'm3': '', 'm2': 'r', 'dt': '', 'p2': '(EP|PPE)', 'p3': '', 'p1': 'CERN', 'f': '', 'p': '', 'recid': -1, 'aas': 0, 'em': '', 'f1': 'reportnumber', 'f2': 'division', 'f3': '', 'uid': 0, 'datetext2': '', 'datetext1': '', 'ec': None, 'ap': 0, 'tab': '', 'id': -1, 'd2y': 0, 'sysnb': '', 'req': None, 'sysno': '', 'rg': None, 'd2m': 0, 'rm': '', 'd1': '', 'd2d': 0, 'wl': 0, 'sc': 0, '_': <function unicode_gettext_wrapper at 0x7f9f8b090e60>, 'c': [''], 'of': 'id', 'sp': '', 'd1y': 0, 'd1d': 0, 'so': 'a', 'recidb': -1, 'action': '', 'd1m': 0, 'ot': '', 'idb': -1, 'sf': ''}).
  ap=0)

2015-04-02 15:17:02 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/oairepository/updater.py:148: UserWarning: Deprecated perform_request_search({'op1': '', 'op2': '', 'cc': 'Atlantis Institute of Fictive Science', 'd2': '', 'verbose': 0, 'jrec': 0, 'ln': 'en', 'selected_external_collections_infos': None, 'm1': 'a', 'm3': '', 'm2': 'e', 'dt': '', 'p2': 'TH', 'p3': '', 'p1': 'CERN', 'f': '', 'p': '', 'recid': -1, 'aas': 0, 'em': '', 'f1': 'reportnumber', 'f2': 'division', 'f3': '', 'uid': 0, 'datetext2': '', 'datetext1': '', 'ec': None, 'ap': 0, 'tab': '', 'id': -1, 'd2y': 0, 'sysnb': '', 'req': None, 'sysno': '', 'rg': None, 'd2m': 0, 'rm': '', 'd1': '', 'd2d': 0, 'wl': 0, 'sc': 0, '_': <function unicode_gettext_wrapper at 0x7f9f8b090e60>, 'c': [''], 'of': 'id', 'sp': '', 'd1y': 0, 'd1d': 0, 'so': 'a', 'recidb': -1, 'action': '', 'd1m': 0, 'ot': '', 'idb': -1, 'sf': ''}).
  ap=0)

2015-04-02 15:17:02 --> 0 recids are missing an oaiid
2015-04-02 15:17:02 --> 3 recids should no longer be exported
2015-04-02 15:17:02 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/oairepository/updater.py:365: UserWarning: Deprecated get_record(10).
  record = get_record(recid)

2015-04-02 15:17:06 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/oairepository/updater.py:365: UserWarning: Deprecated get_record(14).
  record = get_record(recid)

2015-04-02 15:17:06 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/oairepository/updater.py:365: UserWarning: Deprecated get_record(18).
  record = get_record(recid)

2015-04-02 15:17:06 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/oairepository/updater.py:365: UserWarning: Deprecated get_record(98).
  record = get_record(recid)

2015-04-02 15:17:06 --> Wrote to file /home/jnotarst/.virtualenvs/invenio2/var/tmp-shared/oairepository_20150402_151702_FAGYN5
2015-04-02 15:17:06 --> Task #7 finished. [DONE]
2015-04-02 15:17:11 --> Task #8 started.
2015-04-02 15:17:11 --> Input file '/home/jnotarst/.virtualenvs/invenio2/var/tmp-shared/oairepository_20150402_151702_FAGYN5', input mode 'correct'.
2015-04-02 15:17:11 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:301: UserWarning: Deprecated get_record(10).
  rec_old = get_record(rec_id)

2015-04-02 15:17:14 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:304: UserWarning: Deprecated get_record(10).
  original_record = get_record(rec_id)

2015-04-02 15:17:14 --> Record 10 DONE
2015-04-02 15:17:14 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:301: UserWarning: Deprecated get_record(14).
  rec_old = get_record(rec_id)

2015-04-02 15:17:14 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:304: UserWarning: Deprecated get_record(14).
  original_record = get_record(rec_id)

2015-04-02 15:17:14 --> Record 14 DONE
2015-04-02 15:17:14 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:301: UserWarning: Deprecated get_record(18).
  rec_old = get_record(rec_id)

2015-04-02 15:17:14 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:304: UserWarning: Deprecated get_record(18).
  original_record = get_record(rec_id)

2015-04-02 15:17:14 --> Record 18 DONE
2015-04-02 15:17:14 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:301: UserWarning: Deprecated get_record(98).
  rec_old = get_record(rec_id)

2015-04-02 15:17:14 --> /home/jnotarst/.virtualenvs/invenio2/src/invenio/invenio/legacy/bibupload/engine.py:304: UserWarning: Deprecated get_record(98).
  original_record = get_record(rec_id)

2015-04-02 15:17:14 --> Record 98 DONE
2015-04-02 15:17:14 --> Uploading BDR and BDM fields
2015-04-02 15:17:14 --> Task stats: 4 input records, 4 updated, 0 inserted, 0 errors, 0 inserted to holding pen.  Time 3.94 sec.
2015-04-02 15:17:14 --> Task #8 finished. [DONE]
>>> Going to load demo records...
>>> Demo records loaded successfully.
>>> You can define your own post handler for `demosite populate`
>>> Loading demosite data for BibCirculation ...
>>> There are 5 tables to be loaded.
>>> BibCirculation demosite data has been loaded.