DOC: add some explanations about the way we log
authorWilfried Goesgens <dothebart@citadel.org>
Mon, 3 Sep 2012 21:23:03 +0000 (23:23 +0200)
committerWilfried Goesgens <dothebart@citadel.org>
Mon, 3 Sep 2012 21:23:03 +0000 (23:23 +0200)
citadel/techdoc/logging.txt [new file with mode: 0644]

diff --git a/citadel/techdoc/logging.txt b/citadel/techdoc/logging.txt
new file mode 100644 (file)
index 0000000..425683d
--- /dev/null
@@ -0,0 +1,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.
+
+
+