File: logging.txt

package info (click to toggle)
citadel 917-2
  • links: PTS, VCS
  • area: main
  • in suites: buster
  • size: 3,976 kB
  • sloc: ansic: 44,751; sh: 4,209; yacc: 651; makefile: 399
file content (149 lines) | stat: -rw-r--r-- 6,599 bytes parent folder | download | duplicates (3)
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
143
144
145
146
147
148
149
=====Logging =====
Note: the logging scheme is not yet persistant all over the citserver. 

citadel server has several components that emmit different log strings. Its designed so you can filter for specific sessions. 

Since there are several sources for numbering schemes, several numbers need to be employed to make one job / session completely traceable.
The syntax is in general like CC[%d] 


=== CC - Citadel Context ===
All contexts that are visible to the RWHO command have a citadel context.  The ID of such a context is generated from a source that can grow and shrink again. Thus CC may not be uniq to one session.

Citadel may have several kind of sessions: 
  - sessions generated by external connections; they have a CC.
  - sessions spawned by repetive tasks; they at first may have their own id-range, then later on an IO (AsyncIO) and CC (Citadel Context)

=== Identifieing running sessions ===
The RWHO command will list you the currently active CCs:

# sendcommand RWHO
sendcommand: started (pid=14528) connecting to Citadel server at /var/run/citadel/citadel-admin.socket
200 potzblitz Citadel server ADMIN CONNECTION ready.
RWHO
100  
576|SYS_rssclient||http://xkcd.org/rss.xml||0||.||||0
1965|willi|Mail|PotzBlitz|IMAP session|1346695500|    |.||||1
sendcommand: processing ended.

576 is the CC connected to this client. with 

grep 'CC\[576\]' /var/log/syslog 

will show you the loglines from all contexts that had the ID 576; the one named above is an RSS aggregator:

Jul  3 09:07:01 PotzBlitz citserver[1435]: EVCURL:IO[576]CC[576] error description: The requested URL returned error: 404
Jul  3 09:07:01 PotzBlitz citserver[1435]: EVCURL:IO[576]CC[576] error performing request: HTTP response code said error
Jul  3 09:07:01 PotzBlitz citserver[1435]: IO[576]CC[576][29]RSSPneed a 200, got a 404 !


grep 'CC\[1965\]' /var/log/syslog 
will show you the loglines from all contexts that had the ID 1965; the one named above is an inbound IMAP Connection:

Jul  3 09:05:01 PotzBlitz citserver[12826]: IMAPCC[1965] <plain_auth>
Jul  3 09:05:01 PotzBlitz citserver[12826]: CC[1965]<Lobby> 144 new of 144 total messages
Jul  3 09:05:02 PotzBlitz citserver[12826]: CC[1965]<0000000010.Mail> 1 new of 17 total messages

=== Numbering and prefixes ===

While external sessions will constantly show the same CC (or maybe add their own name space as above with IMAPCC) Its important to understand that not all numbers are available in all situations with sessions from repetive tasks; thus you may need several filters to gather all logmessages belonging to one job.

Generaly once per minute one worker becomes an housekeeping thread; This housekeeper scans the whole system for jobs to start.
Once a job is identified, its detection is logged; neither a CC nor IO are already assigned to this job yet;
but it already has its uniq number assigned to it which is specific to the type of task. 
After the preanalysis of this job is done, it may become an AsyncIO job with a Citadel Context. The job now lives in one of the eventqueues, waiting for external file IO or Database IO or performing some calculation of a new state.    
Some basic IO debug logging may not facilitate the CC or the Job-ID; especialy during HTTP or DNS requests.

=== Debug logging ===
By default citserver will only log information about errors or traffic analysis related errors. If you want to track all a job does, you can enable more logging:

sendcommand LOGP (LOG Print; show status of logs; the following list may increase over time) : 

sendcommand: started (pid=19897) connecting to Citadel server at /var/run/citadel/citadel-admin.socket
200 potzblitz Citadel server ADMIN CONNECTION ready.
LOGP
100 Log modules enabled:
modules|0 <- module loading; unloading etc.

rssclient|0  <- RSS aggregator client debugging; on message level
RSSAtomParser|0 <- debugging the parsing of ATOM / RSS feeds; once a message is isolated, the above logging comes into place again.
curl|0 <- HTTP request logging; i.e. querieing the external RSS resources by http is logged with this.
  
networkqueue|0 <- working through rooms, finding jobs to schedule; reading network spool files, writing them; etc.
networktalkingto|0 <- locked list of network interconnections to circumvent race conditions by simultaneous spooling / sending / receiving
networkclient|0 <- outbound networking connections; this has an IO context.

cares|0 <- asynchroneous nameserver lookup
eventloop|0 <- adding jobs; connecting; timeouts; etc.
eventloopbacktrace|0 <- add stacktraces in certain places; very noisy.

sieve|0 <- sieve filtering of mailboxes
messages|0 <- message processing; loading / printing / saving

imapsrv|0 <- Imap connections
serv_xmpp|0 <- XMPP connections
pop3client|0 <- pop3 aggregators

smtpeventclient|0 <- outbound SMTP connections

sendcommand: processing ended.

If the second column is 1, that debug log is enabled.

You can enable the logging by 3 ways: 
 - sendcommand 'LOGS cares|1' (live)
 - via webcit->aide->Enable/Disable logging of the server components; in an interactive manner
 - via environment variable 'CITADEL_LOGDEBUG' as a coma separated list of facilities to enable; before starting citserver
 - via commandline parameter '-x' as a coma separated list of facilities to enable; please note that this switch used to set the loglevel previously.



eventloop,eventloopbacktrace,cares
  - IO the AsyncIO ID
  - IOQ (Queueing of events into eventqueues)

modules: 
  - modules - module init / registering specific stuff

smtpeventclient
  - S[QueueID][N] where the Queue-ID is the number of the Message to be sent, and N the SMTP-job-ID
  - SMTPCQ infrastructure logging when the housekeeper is checking for SMTP-Delivery jobs to spawn

imapsrv
  - IMAPCC: imap client contexts; commands sent to us from Imap-Clients


networkqueue
  - CC - 

networkclient
  - CC, IO - the context
  - NW[nodename][networkerid] the name of the node we're trying to talk to; the networker connection counter uniq per attempt

curl
  - CURL - logging where we don't have a context
  - CC, IO - the context

RSSClient
  - IO, CC, N, 'RSS'; IO & CC not always available.
  - 'RSSP' - the rss and atom parser


pop3client
  - POP3 IO, CC, N - N the number of that connection

sieve
  - sieve doesn't have CC or IOs, its just ran one at a time serverwide.


xmpp
  - XMPP - whether CC could & should be logged has to be researched and added.

Context
  - 'Context:' context related logging - server infrastructure, cleanup of contexts etc.

messages
  - MSG - CC - the context that is manipulating this message.