source: main/waeup.kofa/branches/uli-py3/docs/source/userdocs/datacenter/logging.rst

Last change on this file was 13075, checked in by Henrik Bettermann, 9 years ago

More docs.

In the documentation we prefer to speak of applicant records and avoid the term application as best as we can.

File size: 20.2 KB
Line 
1.. _logging:
2
3Logfiles
4********
5
6Kofa logs actions, which cause changes to the database or the
7filesystem, in separate human-redable event logfiles. Nearly all
8actions are being logged, except some actions committed by
9applicants and students during registration periods. During these
10data initialization periods, applicants and students are requested
11to edit many fields. Usually they press the 'Save' button quite
12often to backup the data entered so far. Logging all these changes
13would mean filling the logfiles with more or less useless or
14redundant information.
15
16The main purpose of Kofa's logging facilities is to trace changes
17effected by portal officers. Applicants and students can only access
18their own data. They don't have the permission to change anything
19else. Whereas portal officers bear responsibility for the integrity
20of the whole database. Depending on the roles they have, officers
21can add, edit or remove application and study data without leaving a
22trace in the object database itself. Kofa closes this security gap
23by recording nearly all actions of portal officers into various
24event logfiles.
25
26.. note::
27
28  Kofa logs the changing but not the viewing of data (except
29  downloading export files or reports). Also entering (login) end
30  leaving (logout) the portal is **not** being recorded.
31
32Critics may claim that extensive logging may discourage officers
33from working with the portal. Persons in key functions often don't
34want to be controlled or supervised by anybody else. Indeed, Kofa
35does not respond to the desire for this kind of privacy. Datacenter
36managers can search all logfiles and can even see what their
37principles have done with the data. Goal behind is **transparency
38and security**, i.e. transparent data processing and reduction of
39the vulnerability to corruption combined with cutting-edge
40technologies to protect the data against attacks from outside.
41
42Logfiles can not be accessed directly. They can neither be
43downloaded nor viewed entirely online. But the files can be searched
44online for arbitrary `regular expressions`_. The simplest regular
45expression is a single word or a string. A technical description,
46how logfiles are being querried, can be found
47:py:meth:`here<waeup.kofa.datacenter.DataCenter.queryLogfiles>`.
48
49Each line in the logfile means a single log entry. It is composed of
50four parts: a datetime string, the log level (mainly 'INFO'), the id
51of the logged-in user, and a message part. Depending on the module,
52the message part is subdivided into further parts which are
53described below.
54
55
56main.log
57========
58
59All actions in the academic section are logged in ``main.log``.
60Changes of faculties, departments, certificates, courses and
61certificate courses done via pages in the user interface (browser
62page) are recorded in the following form::
63
64  2014-12-11 13:09:22,855 - INFO - admin - browser.pages.DepartmentAddFormPage - added: FAC1/DEP1
65  2014-12-11 13:19:31,755 - INFO - admin - browser.pages.DepartmentManageFormPage - DEP1 - saved: title
66  2014-12-12 13:19:43,255 - INFO - admin - browser.pages.FacultyManageFormPage - removed: DEP1
67
68The message part is composed of the browser page name and the action
69taken. In the example above a department ``DEP1`` was added on
70December 11, 2014 by user ``admin`` in faculty ``FAC1``, the title
71was changed 10 minutes later and, finally, the department was
72entirely removed one day later. In the same way user data and
73configuration data are logged in the main logfile. Examples::
74
75  2015-04-01 08:33:47,474 - INFO - admin - browser.pages.UserManageFormPage - Test edited: roles
76  2015-04-27 09:39:24,073 - INFO - admin - browser.pages.SessionConfigurationAddFormPage - added: 2014
77
78Furthermore, ``main.log`` does contain information about reports::
79
80  2015-04-28 15:34:31,852 - INFO - admin - students.reports.student_statistics.StudentStatisticsReportGeneratorPage - report 3029 created: Student Statistics (session=1989, mode=All, breakdown=faccode)
81  2015-04-28 15:34:37,698 - INFO - admin - students.reports.student_statistics.StudentStatisticsReportPDFView - report 3029 downloaded: StudentStatisticsReport_1989_1990_All_2015-04-28_13-34-36_UTC.pdf
82  2015-04-28 15:36:30,106 - INFO - admin - browser.reports.ReportsContainerPage - report 3029 discarded
83
84the management of documents::
85
86  2015-01-09 17:30:49,819 - INFO - admin - HOWTO - Document created
87  2015-01-09 17:30:49,822 - INFO - admin - documents.browser.DocumentAddFormPage - added: REST Document HOWTO
88
89password change requests and the usage of password mandates::
90
91  2015-04-28 13:42:52,753 - INFO - zope.anybody - browser.pages.ChangePasswordRequestPage - B1234567 - myname@gmail.com
92  2015-04-28 13:43:51,056 - INFO - zope.anybody - PasswordMandate used: B1234567
93
94``zope.anybody`` is the user id of anonnymous (non-logged-in) users.
95
96Some log entries do not contain information about a browser page.
97These entries were generated deeper in the system. The ``Document
98created`` entry, for example, was added by a workflow transition.
99The ``PasswordMandate used`` entry was added by
100:py:meth:`waeup.kofa.mandates.mandate.PasswordMandate.execute` and
101not directly by the browser page which calls this method
102(:py:meth:`waeup.kofa.mandates.browser.MandateView.update`).
103
104``main.log`` is also the place where plugins store information about
105system upgrades. If catalogs have to be re-indexed or new attributes
106of objects have to be initialized, a corresponding message is stored
107in the main logfile.
108
109
110datacenter.log
111==============
112
113All actions in the data center (uploading, processing, downloading
114and deleting of files) are logged in ``datacenter.log``::
115
116  2015-04-29 06:52:23,483 - INFO - admin - browser.pages.DatacenterUploadPage - uploaded: /kofa/trunk/var/datacenter/users_admin.csv
117  2015-04-29 06:52:44,025 - INFO - admin - processed: /kofa/trunk/var/datacenter/users_admin.csv, update mode, 3 lines (0 successful/ 3 failed), 0.129 s (0.0430 s/item)
118  2015-04-29 06:53:10,404 - INFO - admin - browser.pages.DatacenterPage - deleted: users_admin.update.pending.csv
119  2015-04-29 06:54:41,963 - INFO - admin - browser.pages.DatacenterUploadPage - uploaded: /kofa/trunk/var/datacenter/users2_admin.csv
120  2015-04-29 06:54:51,748 - INFO - admin - processed: /kofa/trunk/var/datacenter/users2_admin.csv, create mode, 3 lines (3 successful/ 0 failed), 0.024 s (0.0079 s/item)
121
122In the example above a user data file ``users.csv`` was uploaded and
123processed in update mode. The import failed since the 3 users didn't
124exist. The file was then deleted. User ``admin`` uploaded the file a
125second time. The file name had to be changed because the uploader
126does not allow to upload files with same name twice. The file was
127finally successfully processed in create mode.
128
129Also the export of data (export, download and discard) is recorded
130in detail::
131
132  2015-04-29 06:55:20,485 - INFO - admin - browser.pages.ExportCSVPage - exported: certificates, job_id=3036
133  2015-04-29 06:55:25,697 - INFO - admin - browser.pages.ExportCSVView - downloaded: WAeUP.Kofa_certificates_3036.csv, job_id=3036
134  2015-04-29 06:55:30,579 - INFO - admin - browser.pages.ExportCSVPage - discarded: job_id=3036
135
136
137accesscodes.log
138===============
139
140The creation of access code batches, disabling and re-enabling of
141single access codes and archiving and removal of entire batches is
142logged as follows::
143
144  2015-04-29 08:12:26,091 - INFO - admin - accesscodes.browser.AddBatchPage - created: ABC-1-2015_04_29_06_12_24-admin.csv (1000, 2300.000000)
145  2015-04-29 08:13:07,024 - INFO - admin - accesscodes.browser.BatchContainerSearchPage - disabled: ABC-1-6003657048
146  2015-04-29 08:13:11,502 - INFO - admin - accesscodes.browser.BatchContainerSearchPage - (re-)enabled: ABC-1-6003657048
147  2015-04-29 08:14:13,668 - INFO - admin - accesscodes.browser.BatchContainerPage - archived: ABC-1 (ABC-1_archive-2015_04_29_06_14_13-admin.csv)
148  2015-04-29 08:14:14,152 - INFO - admin - accesscodes.browser.BatchContainerPage - deleted: ABC-1
149
150Not all access code workflow transitions are being logged. Each
151access code has a history attribute which contains a detailed list
152of all transitions. The history is shown on the
153`BatchContainerSearchPage`.
154
155
156applicants.log
157==============
158
159The creation, editing and removal of applicants containers as well
160as editing applicant records is being logged. Also
161the approval of payment tickets and all other payment ticket
162transactions are being recorded in ``applicants.log``. Kofa also
163logs all workflow transitions into both the applicant's history
164attribute and the logfile. Okay, this is somehow redundant, but it
165has proved useful to get a complete overview over all applicant
166data transactions also in the logfile. In return, Kofa does not
167aditionally log actions of browser pages if a workflow transition is
168triggered at the same time. Let's see the example::
169
170  2015-04-29 10:14:40,565 - INFO - admin - applicants.browser.ApplicantsContainerAddFormPage - added: app2015
171  2015-04-29 10:14:45,398 - INFO - admin - applicants.browser.ApplicantsContainerManageFormPage - app2015 - saved: startdate + enddate + application_fee
172  2015-04-29 10:15:08,779 - INFO - admin - app2015_262037 - Application initialized
173  2015-04-29 10:15:28,703 - INFO - admin - app2015_262037 - Application started
174  2015-04-29 10:15:28,704 - INFO - admin - applicants.browser.ApplicantManageFormPage - app2015_262037 - saved: reg_number + sex + course1 + date_of_birth
175  2015-04-29 10:16:27,654 - INFO - admin - applicants.browser.ApplicationFeePaymentAddPage - app2015_262037 - added: p4302953958139
176  2015-04-29 10:16:38,921 - INFO - admin - app2015_262037 - Payment approved
177  2015-04-29 10:16:38,922 - INFO - admin - applicants.browser.OnlinePaymentApprovePage - app2015_262037 - approved: p4302953958139
178  2015-04-29 10:16:58,026 - INFO - admin - app2015_262037 - Application submitted
179  2015-04-29 10:17:01,040 - INFO - admin - applicants.browser.ApplicantManageFormPage - app2015_262037 - saved: course_admitted
180  2015-04-29 10:17:10,978 - INFO - admin - app2015_262037 - Applicant admitted
181  2015-04-29 10:17:10,979 - INFO - admin - applicants.browser.ApplicantManageFormPage - app2015_262037 - saved: locked
182  2015-04-29 10:17:34,135 - INFO - admin - app2015_262037 - Student record created (K1000004)
183  2015-04-29 10:45:15,298 - INFO - admin - app2015_262037 - Applicant record removed
184  2015-04-29 10:45:15,299 - INFO - admin - applicants.browser.ApplicantsRootManageFormPage - removed: app2015
185
186An applicants container was added first. The `startdate`, `enddate`
187and the `application_fee` attributes were edited and a new
188applicant record was added some seconds later. The
189`ApplicantManageFormPage` was opened, `reg_number`, `sex`, `course1`
190and `date_of_birth` was edited and the ``start`` transition was
191selected. This was done in the same transaction. The time difference
192between both log entries is only 0.001s. Furthermore, a payment
193ticket was created and the payment approved. Then the applicant was
194set to ``sumitted``, a `course_admitted` was selected and the
195applicant subsequently admitted. The form was automatically locked
196(see time difference). A student container was created and filled
197with the data from the applicant record. Finally, the entire
198applicants container including its content was removed in the same
199transaction, see time diffence between the last two log entries.
200
201
202students.log
203============
204
205The following example shows a typical Nigerian logfile excerpt for a
206student from the very beginning (student record creation from
207applicant data) till the first registration of courses at level
208100. Such an excerpt can be produced simply by searching for
209``B1234567`` on the ``students.log`` search page::
210
211  2014-12-11 10:21:21,930 - INFO - admin - B1234567 - Record created
212  2014-12-11 10:21:21,935 - INFO - admin - B1234567 - Admitted
213  2014-12-19 05:53:02,760 - INFO - admin - Student Processor - physical_clearance_date_adm - B1234567 - updated: reg_number=12345678AB, physical_clearance_date=FRIDAY 9TH JANUARY 2015
214  2014-12-22 14:16:50,494 - INFO - B1234567 - waeup.kofa.students.browser.OnlinePaymentAddFormPage - B1234567 - added: p4192542104720
215  2014-12-22 14:51:36,959 - INFO - B1234567 - waeup.kofa.interswitch.browser.InterswitchPaymentRequestWebservicePageStudent - B1234567 - valid callback for clearance payment p4192542104720: 00:Approved Successful:4500000:5964:p4192542104720:FBN|WEB|UNIBEN|22-12-2014|02345:000382768769
216  2014-12-22 14:51:36,985 - INFO - B1234567 - waeup.kofa.interswitch.browser.InterswitchPaymentRequestWebservicePageStudent - B1234567 - successful clearance payment: p4192542104720
217  2014-12-22 14:53:09,148 - INFO - B1234567 - B1234567 - Clearance started
218  2014-12-22 14:53:39,983 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: birth_certificate.jpg (birth.JPG)
219  2014-12-22 14:53:54,482 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: acc_let.jpg (acceptance.JPG)
220  2014-12-22 14:54:08,943 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: lga_ident.jpg (LGA.JPG)
221  2014-12-22 14:54:23,541 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: fst_sit_scan.jpg (waec.JPG)
222  2014-12-22 14:54:56,663 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: ref_let.jpg (guarantor.JPG)
223  2014-12-22 14:56:16,039 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: stat_dec.jpg (good.JPG)
224  2014-12-22 14:56:37,895 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: jamb_letter.jpg (JAMB.JPG)
225  2014-12-22 14:56:54,696 - INFO - B1234567 - waeup.kofa.students.browser.StudentClearanceEditFormPage - B1234567 - uploaded: secr_cults.jpg (cult.JPG)
226  2014-12-22 15:02:42,550 - INFO - B1234567 - B1234567 - Clearance requested
227  2015-01-17 11:58:12,643 - INFO - clearanceofficer - B1234567 - Cleared
228  2015-03-10 10:58:46,217 - INFO - B1234567 - waeup.kofa.students.browser.OnlinePaymentAddFormPage - B1234567 - added: p4259815262042
229  2015-03-13 11:38:21,658 - INFO - B1234567 - waeup.kofa.interswitch.browser.InterswitchPaymentRequestWebservicePageStudent - B1234567 - valid callback for schoolfee payment p4259815262042: 00:Approved Successful:4950000:2022:p4259815262042:GTB|WEB|UNIBEN|13-03-2015|001234:0001234566
230  2015-03-13 11:38:22,016 - INFO - B1234567 - waeup.kofa.interswitch.browser.InterswitchPaymentRequestWebservicePageStudent - B1234567 - successful schoolfee payment: p4259815262042
231  2015-03-16 13:01:09,989 - INFO - B1234567 - B1234567 - First school fee payment made
232  2015-03-16 13:03:50,977 - INFO - B1234567 - waeup.kofa.students.browser.StudyLevelEditFormPage - B1234567 - added: PHY124|100|2014
233  2015-03-16 13:05:04,504 - INFO - B1234567 - B1234567 - Courses registered
234  2015-03-28 07:18:21,846 - INFO - admin - Student Processor - Matno_for_upload_25_03_2015-1_admin - B1234567 - updated: student_id=B1234567, matric_number=LSC123456
235
236The log entry format of transactions due to imports is slightly
237different::
238
239  2015-04-30 08:40:51,088 - INFO - admin - Student Processor - studentcreate_admin - B3333333 - updated: state=returning, reg_number=BIA12326, firstname=FRIDAY, middlename=None, lastname=Olonko, sex=m, nationality=NG, matric_number=SSC4444444
240  2015-04-30 08:41:27,179 - INFO - admin - StudentStudyCourse Processor (update only) - studycourseaupdate_admin - B3333333 - updated: entry_mode=ug_pt, certificate=BIA, current_session=2002, entry_session=2002, current_level=100, current_verdict=Z
241
242Two files had been uploaded by admin (``studentcreate.csv`` and
243``studycourseaupdate.csv``, see entries in ``datacenter.log``) and
244subsequently imported with the Student Processor and Student Study
245Course Processor respectively.
246
247As already stated above, not all actions committed by students are
248beeing logged. The student did not only upload a lot of files but
249also edited dozens of fields on the clearance form page and probably
250pressed the 'Save' button very often to backup the data entered so
251far. These backup transactions were skipped. All other transactions
252are being recorded. Some examples of further logfile records are
253listed below.
254
255Setting a temporary password::
256
257  2012-10-20 20:59:28,392 - INFO - admin - students.browser.LoginAsStudentStep1 - W4444444 - temp_password generated: Paa3ZVrV
258
259Deactivating and re-activating students::
260
261  2014-11-15 14:28:49,859 - INFO - admin - students.browser.StudentDeactivatePage - W1111111 - account deactivated
262  2014-11-17 10:19:05,735 - INFO - admin - students.browser.StudentActivatePage - W1111111 - account activated
263
264Rejection of clearance requests (an email is sent and the body of
265the email is stored as comment in the logfile)::
266
267  2014-10-27 12:39:34,499 - INFO - clearanceofficer - students.browser.StudentRejectClearancePage - W2222222 - comment: no credit in english
268
269Approval of payment tickets (which does not automatically goes along
270with a student workflow transition)::
271
272  2012-11-02 12:01:03,022 - INFO - admin - students.browser.OnlinePaymentApprovePage - W1000000 - schoolfee payment approved: p3517158705027
273
274Bed allocation and re-allocation::
275
276  2012-11-07 12:56:26,745 - INFO - W1000000 - waeup.kwarapoly.students.browser.BedTicketAddPage - W1000000 - booked: white-house_W_106_B
277  2013-10-29 11:49:55,048 - INFO - hostelofficer - students.browser.BedTicketRelocationPage - W1000000 - relocated: block-a-upper-hostel_A_118_E
278
279Password changes by students::
280
281  2013-02-19 08:54:50,177 - INFO - K9999999 - students.browser.StudentChangePasswordPage - K9999999 - saved: password
282
283
284payments.log
285============
286
287This file is hidden and can only be accessed directly in the
288filesystem. The payment logger is not needed in the Kofa base
289package. Only `OnlinePaymentApprovePage.update()` writes into the
290``payments.log`` file. The logger is primarily intended for storing
291information about successfull financial transactions via external
292payment gateways (e.g. PayPal, Interswitch, eTranzact). No external
293payment gateway module is configured in the base package.
294
295
296hostels.log
297===========
298
299Whereas the reservation/allocation of bed spaces is being logged in
300``students.log`` (see above), the management of hostels and beds is
301recorded in ``hostels.log``::
302
303  2015-04-30 11:44:29,145 - INFO - admin - hostels.browser.HostelAddFormPage - hostels - added: Hall 1
304  2015-04-30 11:45:29,283 - INFO - admin - hostels.browser.HostelManageFormPage - hall-1 - saved: rooms_per_floor + blocks_for_female
305  2015-04-30 11:46:29,330 - INFO - admin - hostels.browser.HostelManageFormPage - hall-1 - 0 empty beds removed, 10 beds added, 0 occupied beds modified ()
306  2015-04-30 11:47:29,433 - INFO - admin - hostels.browser.HostelManageFormPage - hall-1 - switched: hall-1_A_101_A (reserved), hall-1_A_101_B (reserved), hall-1_A_101_C (reserved), hall-1_A_101_D (reserved)
307  2015-04-30 11:47:59,283 - INFO - admin - hostels.browser.HostelManageFormPage - hall-1 - saved: beds_for_fresh + beds_for_all
308  2015-04-30 11:48:29,498 - INFO - admin - hostels.browser.HostelManageFormPage - hall-1 - 9 empty beds removed, 9 beds added, 1 occupied beds modified (hall-1_A_101_E, )
309  2015-04-30 11:49:29,560 - INFO - admin - hostels.browser.HostelManageFormPage - hall-1 - switched: hall-1_A_101_A (unreserved), hall-1_A_101_B (unreserved), hall-1_A_101_C (unreserved), hall-1_A_101_D (unreserved)
310  2015-04-30 11:50:29,689 - INFO - admin - hostels.browser.HostelManageFormPage - hall-1 - released: hall-1_A_101_D (K1000000)
311  2015-04-30 11:51:29,898 - INFO - admin - hostels.browser.BedManageFormPage - hall-1_A_101_A - saved: owner
312  2015-04-30 11:54:30,163 - INFO - admin - hostels.browser.HostelsContainerManagePage - hostels - deleted: hall-1
313
314In this example, the hostel ``Hall 1`` was added and configured,
315beds were updated, beds were reserved (switched), the hostel
316configuration was changed, beds were updated again, beds were
317unreserved, a single bed was released, a new student was allocated
318and, finally, the entire hostel was removed.
319
320Also all transactions of the Hostel Processor are being logged::
321
322  2015-04-30 11:51:12,840 - INFO - system - Hostel Processor - sample_hostel_data - hall-b - updated: beds_for_pre=['F'], floors_per_block=1, beds_for_final=['A', 'B'], rooms_per_floor=44, blocks_for_male=['C', 'D'], hostel_id=hall-b, sort_id=100, beds_for_returning=['C'], hostel_name=Hall B, beds_for_fresh=['D', 'E'], blocks_for_female=[], beds_for_all=[], beds_reserved=[]
323
324
325
326.. _regular expressions: http://en.wikipedia.org/wiki/Regular_expression
Note: See TracBrowser for help on using the repository browser.