From: Adam Dickmeiss Date: Tue, 22 May 2007 13:03:32 +0000 (+0000) Subject: Extended the access log a bit. More material is logged, such as X-Git-Tag: METAPROXY.1.0.10~4 X-Git-Url: http://sru.miketaylor.org.uk/?a=commitdiff_plain;h=86cf292c69bde833d4f587cbf0fae5c6e7d47c68;p=metaproxy-moved-to-github.git Extended the access log a bit. More material is logged, such as record syntax and result set ID for search. Updated documentation accordingly. --- diff --git a/NEWS b/NEWS index f056fcb..1d1a743 100644 --- a/NEWS +++ b/NEWS @@ -1,5 +1,7 @@ --- 1.0.9 .. +Extended the access log a bit. Updated documentation accordingly. + Switched to GPL v2. Added support for configurable default/force target/vhost for module Z39.50 diff --git a/doc/log.xml b/doc/log.xml index 206cd7d..618b3ce 100644 --- a/doc/log.xml +++ b/doc/log.xml @@ -4,7 +4,7 @@ %idcommon; ]> - + log @@ -35,7 +35,7 @@ filename - Specifies a name of file that log messages is written to. + Specifies a name of log file. @@ -48,74 +48,227 @@ for disabled. The following category attributes are supported: + + access + + + One line log messages inspired by Apache access log entries. + This is a brief message stating the request and response. + This is enabled by default. All other categories are disabled by + default. See the section ACCESS LOG. + + + + request-apdu + + + Z39.50 Request APDU. + + + + response-apdu + + + Z39.50 Response APDU. + + + + apdu + + + Z39.50 APDU (request and response) + + + + request-session + + + Request session. + + + + response-session + + + Response session. + + + + session + + + Session (request and response) + + + + init-options + + + Z39.50 Init Request options + + + + + + + + + + + + + The access log + + The access is is strictly one line per entry and aims for + easy mangling with tools such as awk, grep, perl etc. + Many values may be omitted in the packages in which case a single + dash is printed instead. This is to ensure that all values have + well-defined position. + + + The basic format and order is - access - - - One line log messages inspired by Apache access log entries. - This is a brief message stating the request and response. - This is enabled by default. All other categories are disabled by - default. + time (position 1) + + Full time of event - request-apdu - - - Z39.50 Request APDU. + + Custom message (position 2) + + The string as given in element message. - response-apdu - - - Z39.50 Response APDU. + + IP (position 3) + + IP address of origin (peer) - apdu - - - Z39.50 APDU (request and response) + + session (position 4) + + Session ID. Can be used to identify a particular Z39.50 session. + For HTTP this session ID only tracks the HTTP socket (kept alive). + NOT to be confused the the HTTP cookie mechanism. - request-session - - - Request session. + + elapsed (position 5) + + Elapsed time . + The elapsed time is the time between the point in time + where a package was received form the client and the + point where a response was received from the next filter + in chain (backend eventually). - response-session - - - Response session. + protocol (position 6) + + Protocol type which is one of Z3950 or + HTTP_Request or + HTTP_Response. - session - + + + + + For packages of with protocol marker Z3950 + the the access log line is followed by the APDU type + information + depending on the type. The APDU type is on position 7. + + + + initRequest + + Z39.50 Initialize Request with the information + username, vhost, + implementation ID, implementation name, implementation version. + + + + + initResponse + + Z39.50 Initialize Response with the information: + status (OK or FAIL), implementatino ID, implementation name, + implementation version. + + + + + searchRequest + + Z39.50 Search Request with the information: + database(s), result set ID, record syntax, query. + - Session (request and response) + Multiple databases are separated by + a plus-sign (+). The query itself is + multiple tokens. For this reason it is placed as the last + information on this log entry. - init-options - + + searchResponse + + Z39.50 Search Response with the information: + status (OK or FAIL), hit count, number of records returned, + next result set position. + + + + + presentRequest + + Z39.50 Present Request with the information: + result Set ID, start position, number of records requested, + record syntax, record composition. + + + + + presentResponse + + Z39.50 Present Response with the information: + status (OK, DIAG, ERROR), number of records returned, + next result set position. + + + + + scanRequest + + Z39.50 Scan Request with the information: + database(s), number of terms requested, preferred position in + response, step size, start point. + - Z39.50 Init Request options + start point is a multi token value in PQF notation. - - - + + scanResponse + + Z39.50 Scan Response with the information: + status (OK, ERROR), number of entries returned, position of term, + step size. + + EXAMPLES diff --git a/src/filter_log.cpp b/src/filter_log.cpp index eb33d66..bc22583 100644 --- a/src/filter_log.cpp +++ b/src/filter_log.cpp @@ -1,4 +1,4 @@ -/* $Id: filter_log.cpp,v 1.29 2007-05-09 21:23:09 adam Exp $ +/* $Id: filter_log.cpp,v 1.30 2007-05-22 13:03:32 adam Exp $ Copyright (c) 2005-2007, Index Data. This file is part of Metaproxy. @@ -50,7 +50,7 @@ namespace metaproxy_1 { typedef boost::shared_ptr LFilePtr; public: //Impl(); - Impl(const std::string &x = ""); + Impl(const std::string &x = "-"); ~Impl(); void process(metaproxy_1::Package & package) const; void configure(const xmlNode * ptr); diff --git a/src/gduutil.cpp b/src/gduutil.cpp index 9b1ae5a..7fd718f 100644 --- a/src/gduutil.cpp +++ b/src/gduutil.cpp @@ -1,4 +1,4 @@ -/* $Id: gduutil.cpp,v 1.21 2007-05-09 21:23:09 adam Exp $ +/* $Id: gduutil.cpp,v 1.22 2007-05-22 13:03:32 adam Exp $ Copyright (c) 2005-2007, Index Data. This file is part of Metaproxy. @@ -133,60 +133,74 @@ std::ostream& std::operator<<(std::ostream& os, Z_DefaultDiagFormat& ddf) return os; } +static void dump_opt_string(std::ostream& os, const char *s) +{ + os << " "; + if (s) + os << s; + else + os << "-"; +} + +static void dump_opt_int(std::ostream& os, const int *i) +{ + os << " "; + if (i) + os << *i; + else + os << "-"; +} + std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) { switch(zapdu.which) { case Z_APDU_initRequest: - os << " " << "initRequest" << " "; + os << " " << "initRequest"; { Z_InitRequest *ir = zapdu.u.initRequest; Z_IdAuthentication *a = ir->idAuthentication; - if (a && a->which == Z_IdAuthentication_idPass - && a->u.idPass->userId) - os << a->u.idPass->userId << " "; - //<< ":" << a->u.idPass->groupId << " "; + if (a && a->which == Z_IdAuthentication_idPass) + dump_opt_string(os, a->u.idPass->userId); + else if (a && a->which == Z_IdAuthentication_open) + dump_opt_string(os, a->u.open); else - os << "-" << " "; - + dump_opt_string(os, 0); + + os << " "; std::list vhosts; mp::util::get_vhost_otherinfo(ir->otherInfo, vhosts); if (vhosts.size()){ copy(vhosts.begin(), vhosts.end(), ostream_iterator(os, " ")); } - else - os << "-" << " " ; - - if (ir->implementationId) - os << (ir->implementationId) << " "; - //<< ir->referenceId << " " - if (ir->implementationName) - os<< (ir->implementationName) << " "; - if (ir->implementationVersion) - os << (ir->implementationVersion) << " "; + else + os << "-" ; + + dump_opt_string(os, ir->implementationId); + dump_opt_string(os, ir->implementationName); + dump_opt_string(os, ir->implementationVersion); } break; case Z_APDU_initResponse: - os << " " << "initResponse" << " "; + os << " " << "initResponse "; { Z_InitResponse *ir = zapdu.u.initResponse; - if (ir->result && *(ir->result)){ - os << "OK" << " "; - if (ir->implementationId) - os << (ir->implementationId) << " "; - //<< ir->referenceId << " " - if (ir->implementationName) - os<< (ir->implementationName) << " "; - if (ir->implementationVersion) - os << (ir->implementationVersion) << " "; + if (ir->result && *(ir->result)) + { + os << "OK"; } else - os << "DIAG"; + { + os << "FAIL"; + } + dump_opt_string(os, ir->implementationId); + dump_opt_string(os, ir->implementationName); + dump_opt_string(os, ir->implementationVersion); } break; case Z_APDU_searchRequest: @@ -198,12 +212,25 @@ std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) for (int i = 0; i < sr->num_databaseNames; i++) { os << sr->databaseNames[i]; - if (i+1 == sr->num_databaseNames) - os << " "; - else + if (i+1 != sr->num_databaseNames) os << "+"; } - + + dump_opt_string(os, sr->resultSetName); + + os << " "; + if (sr->preferredRecordSyntax) + { + char oid_name_str[OID_STR_MAX]; + const char *oid_name = yaz_oid_to_string_buf( + sr->preferredRecordSyntax, 0, oid_name_str); + + os << oid_name; + } + else + os << "-"; + + os << " "; WRBUF wr = wrbuf_alloc(); yaz_query_to_wrbuf(wr, sr->query); os << wrbuf_cstr(wr); @@ -211,26 +238,16 @@ std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) } break; case Z_APDU_searchResponse: - os << " " << "searchResponse" << " "; + os << " " << "searchResponse "; { Z_SearchResponse *sr = zapdu.u.searchResponse; if (sr->searchStatus && *(sr->searchStatus)) { os << "OK"; - if (sr->resultCount) - os << " " << *(sr->resultCount); - else - os << " -"; - //<< sr->referenceId << " " - if (sr->numberOfRecordsReturned) - os << " " << *(sr->numberOfRecordsReturned); - else - os << " -"; - if (sr->nextResultSetPosition) - os << " " << *(sr->nextResultSetPosition); - else - os << " -"; + dump_opt_int(os, sr->resultCount); + dump_opt_int(os, sr->numberOfRecordsReturned); + dump_opt_int(os, sr->nextResultSetPosition); } else if (sr->records) @@ -243,19 +260,9 @@ std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) os << " " << "presentRequest"; { Z_PresentRequest *pr = zapdu.u.presentRequest; - if (pr->resultSetId) - os << " " << (pr->resultSetId); - else - os << " -"; - //<< pr->referenceId << " " - if (pr->resultSetStartPoint) - os << " " << *(pr->resultSetStartPoint); - else - os << " -"; - if (pr->numberOfRecordsRequested) - os << " " << *(pr->numberOfRecordsRequested); - else - os << " -"; + dump_opt_string(os, pr->resultSetId); + dump_opt_int(os, pr->resultSetStartPoint); + dump_opt_int(os, pr->numberOfRecordsRequested); if (pr->preferredRecordSyntax) { char oid_name_str[OID_STR_MAX]; @@ -267,11 +274,9 @@ std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) else os << " -"; const char * msg = 0; - if (pr->recordComposition - && (msg = mp_util::record_composition_to_esn(pr->recordComposition))) - os << " " << msg; - else - os << " -"; + if (pr->recordComposition) + msg = mp_util::record_composition_to_esn(pr->recordComposition); + dump_opt_string(os, msg); } break; case Z_APDU_presentResponse: @@ -343,24 +348,14 @@ std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) for (int i = 0; i < sr->num_databaseNames; i++) { os << sr->databaseNames[i]; - if (i+1 == sr->num_databaseNames) - os << " "; - else - os << "+"; + if (i+1 != sr->num_databaseNames) + os << "+"; } - if (sr->numberOfTermsRequested) - os << " " << *(sr->numberOfTermsRequested); - else - os << " -"; - if (sr->preferredPositionInResponse) - os << " " << *(sr->preferredPositionInResponse); - else - os << " -"; - if (sr->stepSize) - os << " " << *(sr->stepSize); - else - os << " -"; - + dump_opt_int(os, sr->numberOfTermsRequested); + dump_opt_int(os, sr->preferredPositionInResponse); + dump_opt_int(os, sr->stepSize); + + os << " "; if (sr->termListAndStartPoint) { WRBUF wr = wrbuf_alloc(); @@ -370,7 +365,7 @@ std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) wrbuf_destroy(wr); } else - os << " -"; + os << "-"; } } break; @@ -381,61 +376,41 @@ std::ostream& std::operator<<(std::ostream& os, Z_APDU& zapdu) = zapdu.u.scanResponse; if (sr) { - if ((sr->scanStatus) && !*(sr->scanStatus)) + if (!sr->scanStatus) { os << "OK"; - //<< *(sr->scanStatus) << " " - if (sr->numberOfEntriesReturned) - os << " " << *(sr->numberOfEntriesReturned); - else - os << " -"; - //<< sr->referenceId << " " - if (sr->positionOfTerm) - os << " " << *(sr->positionOfTerm); - else - os << " -"; - if (sr->stepSize) - os << " " << *(sr->stepSize); - else - os << " -"; } - else { - os << "ERROR"; - if (sr->scanStatus) - { - os << " " << *(sr->scanStatus) << " "; - - switch (*(sr->scanStatus)){ - case Z_Scan_success: - os << "success "; - break; - case Z_Scan_partial_1: - os << "partial_1"; - break; - case Z_Scan_partial_2: - os << "partial_2"; - break; - case Z_Scan_partial_3: - os << "partial_3"; - break; - case Z_Scan_partial_4: - os << "partial_4"; - break; - case Z_Scan_partial_5: - os << "partial_5"; - break; - case Z_Scan_failure: - os << "failure"; - break; - default: - os << "unknown"; - } + else + { + switch (*(sr->scanStatus)){ + case Z_Scan_success: + os << "OK"; + break; + case Z_Scan_partial_1: + os << "partial_1"; + break; + case Z_Scan_partial_2: + os << "partial_2"; + break; + case Z_Scan_partial_3: + os << "partial_3"; + break; + case Z_Scan_partial_4: + os << "partial_4"; + break; + case Z_Scan_partial_5: + os << "partial_5"; + break; + case Z_Scan_failure: + os << "failure"; + break; + default: + os << "unknown"; } - if (sr->numberOfEntriesReturned) - os << " " << *(sr->numberOfEntriesReturned); - else - os << " -"; } + dump_opt_int(os, sr->numberOfEntriesReturned); + dump_opt_int(os, sr->positionOfTerm); + dump_opt_int(os, sr->stepSize); } } break;