/*****************************************************************************/ /* Logging.c Logging functions for the WASD VMS HTTPd. By default, produces a Web "common" format log suitable for analysis by tools capable of processing that format. Secretes four pseudo-requests logging the BEGINing, OPENing, CLOSEing and ENDing of logging activities. These shouldn't introduce problems for analysis tools as they look like legitimate POST entries for user "HTTPd"! The [LogFormat] directive generates logs in the "common+server", "combined" and a user-defined format. If a user-defined format contains an error the server will exit the first time a request is logged. Caveat emptor! Log file name must be supplied via [LogFile] or the logical name WASD_CONFIG_LOG (process, job, or system level). An error is reporting if logging is enabled without either of these being supplied. If the log file name specified is "SYS$OUTPUT" log entries are written to SYS$OUTPUT. This is useful for checking user-defined log entries before committing files to that format. The [LogNaming] format can be any of "NAME" (default) which names the log file using the first period-delimited component of the IP host name, "HOST" which uses as much of the IP host name as can be accomodated within the maximum 39 character filename limitation (of ODS-2), or "ADDRESS" which uses the full IP host address in the name. Both HOST and ADDRESS have hyphens substituted for periods in the string. If these are specified then by default the service port follows the host name component. This may be suppressed using the [LogPerServiceHostOnly] directive, allowing a minimum extra 3 characters in the name, and combining entries for all ports associated with the host name. The log file can have a [LogPeriod] associated with it. This period determines when a new log file is created. The periods are hourly, daily, weekly and monthly. An hourly period is indicated by HOURLY, a daily period by DAILY, a weekly period by MONDAY, TUESDAY, WEDNESDAY, THURSDAY, FRIDAY, SATURDAY and SUNDAY (the day of the week on which, at midnight or the first request thereafter, the log is recreated), and finally a monthly recreation by MONTHLY. The WASD_CONFIG_LOG logical is then used merely for the directory component and the file name is fixed at HOST_YYYYMMDD_ACCESS.LOG where host is the first dot-separated component of the primary IP host name and YYYY, MM, DD is the year, month and day the log was created, or if hourly period has been specified HOST_YYYYMMDDHH_ACCESS.LOG where the additional HH represents the hour the log was created. When multiple instances, either on the one node or across a cluster, are writing to the same log file (multi-stream), then RMS insists on automatically flushing each log record write (considering the issues with maintaining 'dirty' buffers, perhaps cluster-wide, this is not unreasonable). This does increase the physical disk I/O significantly though, and of course reduces server performance equally (or more so) as a result. The simple (and effective) solution to this is to have only one stream writing to a log file at the one time. This is enabled using the [LogPerInstance] configuration directive. With this active each log file has the node name and then the instance process name appended to the .LOG file type resulting in names similar to (for a two instance single node) 10-168-0-3_80_20020527_ACCESS.LOG_KLAATU_HTTPD-80 10-168-0-3_80_20020527_ACCESS.LOG_KLAATU_HTTPE-80 10-168-0-3_443_20020527_ACCESS.LOG_KLAATU_HTTPD-80 10-168-0-3_443_20020527_ACCESS.LOG_KLAATU_HTTPE-80 Of course these need to be integrated at some stage, either using one of the many log file analysis tools, or a specific utility such as WASD's CALOG.C (Consolidate Access LOGs, pronounced as with the breakfast cereals). COMMON FORMAT ------------- (NCSA, CERN, etc.) 'client rfc1413 auth-user date/time request status bytes' COMBINED FORMAT --------------- (NCSA) 'client rfc1413 auth-user date/time request status bytes referer user-agent' COMMON FORMAT plus server name ------------- (NCSA, CERN, etc.) 'client rfc1413 auth-user date/time request status bytes server' USER-DEFINED FORMAT ------------------- Must begin with a character that is used as a substitute when a particular field is empty (use "\0" for no substitute, as in the "windows log format" example below). Two different "escape" characters introduce the following parameters of characters. A '!' followed by ... 'AR' : authentication realm - none 'AU' : authenticated user name - Apache %u 'BB' : longword bytes in body (excluding response header) - Apache %b 'BQ' : quadword bytes transmitted to the client - none 'BY' : longword bytes transmitted to the client - none 'CA' : client numeric address - Apache %a 'CC' : X509 client certificate authorization distinguishing name - none 'CN' : client host name (or address if DNS lookup disabled) - Apache %h 'CP' : client port 'EM' : request elapsed time in milliseconds - none 'ES' : request elapsed time in fractional seconds 'ET' : request elapsed time in seconds - Apache %T 'EU' : request elapsed time in microseconds - none 'HO' : "Host:" request header 'ID' : session track ID - none 'ME' : request method - none 'PA' : request path (NOTE: not the full request path! See 'R') - none 'PP' : outgoing proxy connection local port 'PR' : HTTP protocol (e.g. "HTTP/1.1") - none 'QS' : request query string - none 'RF' : referer - Apache %{referer}i 'RH' : the specified request header (e.g. "RH:cache-control:") 'RQ' : FULL request path (script and any query string) - Apache %r 'RS' : response status code - none 'SC' : script name - none 'SM' : request scheme name (i.e. "http:" or "https:") - none 'SN' : server host name (virtual) - Apache %v 'SP' : server port - Apache %p 'TC' : request time (common log format) - Apache %t 'TG' : request time (GMT) - none 'TV' : request time (VMS format) - none 'UA' : user agent - Apache %{user-agent}i 'VS' : virtual service (actual service host:port used by the request) A '\' followed by ... '0' : a null character (used to define the empty field character) '!' : insert an '!' '\' : insert a '\' 'n' : insert a newline 'q' : insert a quote (so that in the DCL the quotes won't need escaping!) 't' : insert a TAB Any other character is directly inserted into the log entry. Examples -------- The equivalent of the common log format is: "-!CN !ID !AU [!TC] \q!RQ\q !RS !BY" The combined log format: "-!CN !ID !AU [!TC] \q!RQ\q !RS !BY \q!RF\q \q!UA\q" The WebSite "windows log format" would be created by: "\0!TC\t!CA\t!SN\t!AR\t!AU\t!ME\t!PA\t!RQ\t!EM\t!UA\t!RS\t!BB\t" To get the common log format plus append request duration in seconds: "-!CN !ID !AU [!TC] \q!RQ\q !RS !BY !ES" VERSION HISTORY --------------- 09-APR-2011 MGD 'PP' outgoing proxy connection local port 04-FEB-2010 MGD 'HO' request "Host:" field 'RH' any request header (e.g. "RH:cache-control:") 'VS' virtual service used by the host bugfix; LoggingDo() sys$flush(&RAB) not (&FAB) 01-FEB-2010 MGD bugfix; LoggingDo() initialise (zero) &DummyRequest 15-NOV-2009 MGD bugfix; whatever happened to 'CN'? 13-OCT-2009 MGD allow for []-delimited IPv6 addresses as service names 26-MAY-2009 MGD 'CP' for client port per-service user-defined log format 04-NOV-2006 MGD bugfix; LoggingDo() changes for daily period test to support hourly logging (thanks again JPP) LOGGING_SHUT to a close log file (without disabling logging) 30-SEP-2006 MGD add HOURLY period remove file name length constraint for logs created on an ODS-5 volume (allows full host name components, etc.) 26-JAN-2006 MGD bugfix; 'RQ' include method and protocol (Apache "%r") bugfix; 'EM', 'ES' and 'UE' arithmetic ('doh'!?) 'ET' (equivalent of Apache "%T") 12-OCT-2004 MGD configurable service unavailable 503 when log write fails 04-SEP-2004 MGD 'BQ' for quadword bytes tx 04-AUG-2004 MGD refine end-of-period log file handling 04-MAR-2004 MGD timestamp entry, server account username 28-JAN-2004 MGD LoggingReport(), add HTTP protocol to timestamp and pseudo entries 28-JUN-2003 MGD bugfix; add HTTP protocol to combined/common format URL 'PR' same datum with user format (jf.pieronne@laposte.fr) 08-APR-2003 MGD timestamp and pseudo entry formats, make bytes numeric and leading slash before server POST paths (e.g. "/KLAATU::..") (Analog could complain about both of these), add the server software ID as the user-agent field 26-MAY-2002 MGD logging per-instance 21-DEC-2001 MGD bugfix; 07-NOV-2001 for ALL services :^} 07-NOV-2001 MGD bugfix; close current log file if period changes 25-OCT-2001 MGD timestamp log file(s) every hour, FAB$M_TEF to deallocate unused file space 04-AUG-2001 MGD support module WATCHing 04-MAY-2001 MGD increased LoggingDo() 'String' size from 2048 TO 4096 20-MAR-2001 MGD added FAB$M_DFW, w_deq=nnn, b_mbc=127, improves log performance by 500%!! (jfp@altavista.net) 15-DEC-2000 MGD client certificate authorization (as rfc1413 & 'CC') 15-OCT-2000 MGD correct time string TZ (GMT format) 07-MAY-2000 MGD session track ID 16-FEB-2000 MGD "[LogNaming] HOST", [LogPerServiceHostOnly] processing 12-JUN-1999 MGD modify WATCH log entry format 22-MAR-1999 MGD increased LoggingDo() 'String' size from 1024 to 2048 07-NOV-1998 MGD WATCH facility 27-AUG-1998 MGD exclude specified hosts from being logged 17-MAY-1998 MGD add per-service logging 23-NOV-1997 MGD signal failed log file create/put (e.g. disk quota :^) 25-OCT-1997 MGD log file period new for v4.5, log file now opened for sharing GET, PUT and UPD added 'CI' (cache-involvement) user-format directive bugfix; user format from configuration file 25-SEP-1997 MGD bugfix; ACCVIO if request structure exists but empty (assumed if it existed all the pointers were valid - WRONG!) 06-SEP-1997 MGD added "common+server", "combined", "user-defined" log formats 10-JUL-1997 MGD minor modification for server-admin logging on/off/flush 10-JUL-1996 MGD RequestUriPtr instead of ScriptPtr/PathInfoPtr/QueryStringPtr 01-DEC-1995 MGD HTTPd version 3, "common" log format 27-SEP-1995 MGD use time values in request thread structure 16-JUN-1995 MGD added node name, changed logging fields to be space-separated 07-APR-1995 MGD initial development for addition to multi-threaded daemon */ /*****************************************************************************/ #ifdef WASD_VMS_V7 #undef _VMS__V6__SOURCE #define _VMS__V6__SOURCE #undef __VMS_VER #define __VMS_VER 70000000 #undef __CRTL_VER #define __CRTL_VER 70000000 #endif /* standard C header files */ #include #include #include #include /* VMS related header files */ #include #include #include #include #include #include /* application header files */ #include "wasd.h" #include "httpd.h" #include "error.h" #include "logging.h" #define WASD_MODULE "LOGGING" #define LOGGING_NAMING_NAME 1 #define LOGGING_NAMING_HOST 2 #define LOGGING_NAMING_ADDRESS 3 /******************/ /* global storage */ /******************/ char ErrorLoggingFormatLength [] = "log format too long"; int LoggingDayWeekBegins; BOOL LoggingEnabled, LoggingNaming, LoggingPerPeriod, LoggingPerService, LoggingPeriodHourly, LoggingPeriodDaily, LoggingPeriodWeekly, LoggingPeriodMonthly, LoggingProxyLocalPort, LoggingSysOutput, LoggingFileError; int LoggingFileNameLength, LoggingNaming, LoggingTimeStampCount; char LoggingFileName [256], LoggingFormatUser [128], LoggingPeriodName [128]; /********************/ /* external storage */ /********************/ extern BOOL CliLoggingDisabled, CliLoggingEnabled; extern int ExitStatus, HttpdDayOfWeek, HttpdTickSecond, ServerPort; extern int ToLowerCase[], ToUpperCase[]; extern unsigned short HttpdNumTime[]; extern unsigned long HttpdBinTime[], SysPrvMask[]; extern char CliLoggingPeriod[], ErrorSanityCheck[], ServerHostName[], SoftwareID[], TimeGmtString[]; extern CONFIG_STRUCT Config; extern HTTPD_PROCESS HttpdProcess; extern META_CONFIG *MetaGlobalServicePtr; extern SERVICE_STRUCT *ServiceListHead; extern SYS_INFO SysInfo; extern WATCH_STRUCT Watch; /*****************************************************************************/ /* Parameter 'Function' can be: LOGGING_BEGIN server startup LOGGING_OPEN open server logging, other than server startup LOGGING_CLOSE close server logging, other than server shutdown LOGGING_END server shutdown LOGGING_ENTRY log a request LOGGING_SHUT shut (close) the log files LOGGING_TIMESTAMP put a timestamp pseudo-entry into the log file LOGGING_FLUSH close the log file, flushing the contents With per-service logging most of these functions must be performed on each service's log, logging a request entry occurs for the service involved only. */ int Logging ( REQUEST_STRUCT *rqptr, int Function ) { BOOL PrevLoggingEnabled, WatchThisOne; int status; char *cptr, *sptr; SERVICE_STRUCT *svptr; /*********/ /* begin */ /*********/ if (WATCHING(rqptr) && WATCH_MODULE(WATCH_MOD__OTHER)) WatchThis (rqptr, FI_LI, WATCH_MOD__OTHER, "Logging() !UL", Function); if (!rqptr && WATCH_CATEGORY(WATCH_LOG)) WatchThisOne = true; else if (rqptr) { if (WATCHING(rqptr) && WATCH_CATEGORY(WATCH_LOG)) WatchThisOne = true; else WatchThisOne = false; } else WatchThisOne = false; switch (Function) { case LOGGING_ENTRY : if (!LoggingEnabled) return (STS$K_ERROR); /* if the request path has been mapping-rule set NOlog then don't! */ if (rqptr && rqptr->rqPathSet.NoLog) { if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "NOLOG !AZ", rqptr->rqHeader.PathInfoPtr); return (SS$_NORMAL); } if (Config.cfLog.ExcludeHostsPtr && rqptr) { sptr = Config.cfLog.ExcludeHostsPtr; while (*sptr) { if (isdigit(*sptr)) cptr = rqptr->rqClient.IpAddressString; else cptr = rqptr->rqClient.Lookup.HostName; while (*cptr) { if (*sptr == STRING_LIST_CHAR) break; if (*sptr == '*') { while (*sptr && *sptr == '*' && *sptr != STRING_LIST_CHAR) sptr++; while (*cptr && *cptr != *sptr) cptr++; } if (TOLO(*cptr) != TOLO(*sptr)) break; if (*cptr) cptr++; if (*sptr) sptr++; } if (!*cptr && (!*sptr || *sptr == STRING_LIST_CHAR)) break; while (*sptr && *sptr != STRING_LIST_CHAR) sptr++; if (*sptr) sptr++; } /* if it was found then return without logging the request */ if (!*cptr && (!*sptr || *sptr == STRING_LIST_CHAR)) { if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "EXCLUDE !AZ", rqptr->rqClient.Lookup.HostName); return (SS$_NORMAL); } } if (rqptr->ServicePtr->NoLog) { if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "NOLOG for !AZ//!AZ", rqptr->ServicePtr->RequestSchemeNamePtr, rqptr->ServicePtr->ServerHostPort); return (STS$K_ERROR); } if (LoggingPerService) status = LoggingDo (rqptr, rqptr->ServicePtr, Function, WatchThisOne); else status = LoggingDo (rqptr, ServiceListHead, Function, WatchThisOne); return (status); case LOGGING_BEGIN : case LOGGING_CLOSE : case LOGGING_END : case LOGGING_FLUSH : case LOGGING_OPEN : case LOGGING_SHUT : case LOGGING_TIMESTAMP : switch (Function) { case LOGGING_BEGIN : if (Config.cfLog.Enabled || CliLoggingEnabled) LoggingEnabled = true; if (CliLoggingDisabled) LoggingEnabled = false; LoggingPerService = Config.cfLog.PerService || Config.cfLog.PerServiceHostOnly; /* in log using host part of file name, name or address? */ LoggingNaming = LOGGING_NAMING_NAME; if (Config.cfLog.Naming[0]) { if (strsame (Config.cfLog.Naming, "NAME", -1)) LoggingNaming = LOGGING_NAMING_NAME; else if (strsame (Config.cfLog.Naming, "HOST", -1)) LoggingNaming = LOGGING_NAMING_HOST; else if (strsame (Config.cfLog.Naming, "ADDRESS", -1)) LoggingNaming = LOGGING_NAMING_ADDRESS; else FaoToStdout ("%HTTPD-W-LOG, naming unknown\n \\!AZ\\\n", Config.cfLog.Naming); } break; case LOGGING_OPEN : if (LoggingEnabled) return (STS$K_ERROR); break; default : if (!LoggingEnabled) return (STS$K_ERROR); break; } PrevLoggingEnabled = LoggingEnabled; if (Function == LOGGING_TIMESTAMP) LoggingTimeStampCount++; if (LoggingPerService) { for (svptr = ServiceListHead; svptr; svptr = svptr->NextPtr) { status = LoggingDo (rqptr, svptr, Function, WatchThisOne); if (VMSnok (status)) break; } } else status = LoggingDo (rqptr, ServiceListHead, Function, WatchThisOne); switch (Function) { case LOGGING_BEGIN : if (VMSnok (status)) LoggingEnabled = false; break; case LOGGING_OPEN : if (VMSok (status)) LoggingEnabled = true; else LoggingEnabled = PrevLoggingEnabled; break; case LOGGING_CLOSE : case LOGGING_END : if (VMSok (status)) LoggingEnabled = LoggingFileError = false; else LoggingEnabled = PrevLoggingEnabled; } return (status); default : ErrorExitVmsStatus (SS$_BUGCHECK, ErrorSanityCheck, FI_LI); } } /*****************************************************************************/ /* What an incomprehensibly long function this has grown to be! :^( The 'svptr' parameter points to the service structure associated with the log. If per-service logging is enabled this will be the appropriate one of however many services are created. If per-service logging is not enabled this will always be the first service created (i.e. the "primary" service). Where service information is required for user-format logging it is accessed from the request structure's service pointer. */ int LoggingDo ( REQUEST_STRUCT *rqptr, SERVICE_STRUCT *svptr, int Function, BOOL WatchThisOne ) { # define MAX_FAO_VECTOR 64 static char *MonthName [] = { "", "Jan", "Feb", "Mar", "Apr", "May", "Jun", "Jul", "Aug", "Sep", "Oct", "Nov", "Dec" }; static $DESCRIPTOR (PeriodFileNameFaoDsc, "!#AZ!AZ!AZ_!UL!2ZL!2ZL!AZ_ACCESS.LOG!AZ!AZ!AZ!AZ"); static $DESCRIPTOR (ServiceFileNameFaoDsc, "!#AZ!AZ!AZ_ACCESS.LOG!AZ!AZ!AZ!AZ"); static $DESCRIPTOR (BytesFaoDsc, "!UL\0"); static $DESCRIPTOR (ClientPortFaoDsc, "!UL\0"); static $DESCRIPTOR (QuadBytesFaoDsc, "!@SQ\0"); static $DESCRIPTOR (ElapsedResponseDurationDsc, "!UL\0"); static $DESCRIPTOR (ElapsedSecondsDsc, "!UL.!3ZL\0"); static $DESCRIPTOR (HourlyFaoDsc, "!2ZL\0"); static $DESCRIPTOR (LocalPortFaoDsc, "!UL\0"); static $DESCRIPTOR (StatusFaoDsc, "!UL\0"); static $DESCRIPTOR (VmsTimeFaoDsc, "!%D\0"); static $DESCRIPTOR (LogFileTimeFaoDsc, "!2ZL/!3AZ/!4ZL:!2ZL:!2ZL:!2ZL !3AZ!2AZ"); /* server-host - - [date/time] \"what-status\" 200 0 */ static $DESCRIPTOR (LogFilePseudoFaoDsc, "!AZ !AZ !AZ [!AZ] \"POST /!AZ::!AZ-!AZ-!8XL HTTP/1.1\" 200 0!AZ!AZ!AZ"); /* server-host - - [date/time] \"TIMESTAMP-count\" 200 0 */ static $DESCRIPTOR (LogFileTimeStampFaoDsc, "!AZ !AZ !AZ [!AZ] \"POST /!AZ::!AZ-!AZ-!8ZL HTTP/1.1\" 200 0!AZ!AZ!AZ"); /* host r-ident user [date/time] \"request\" status bytes */ static $DESCRIPTOR (LogFileCommonFaoDsc, "!AZ !AZ !AZ [!AZ] \"!AZ !AZ!AZ\" !UL !AZ"); /* as for "common" above, plus ' server'*/ static $DESCRIPTOR (LogFileCommonServerFaoDsc, "!AZ !AZ !AZ [!AZ] \"!AZ !AZ!AZ\" !UL !AZ !AZ"); /* as for "common" above, plus ' referer user-agent'*/ static $DESCRIPTOR (LogFileCombinedFaoDsc, "!AZ !AZ !AZ [!AZ] \"!AZ !AZ!AZ\" !UL !AZ \"!AZ\" \"!AZ\""); /* user-defined log-file format */ static $DESCRIPTOR (LogFileUserFaoDsc, "!#(AZ)"); static $DESCRIPTOR (LnmFileDevDsc, "LNM$FILE_DEV"); static $DESCRIPTOR (WasdLogNameDsc, "WASD_LOG"); static $DESCRIPTOR (HttpdLogNameDsc, "HTTPD$LOG"); static int ExtendBlocks = LOGGING_DEFAULT_EXTEND_BLOCKS; static unsigned short Length, WeeklyNumTime [7]; static char BytesString [32], ClientPort [16], Elapsed [32], HourlyString [3], ProcessName [16], StatusString [16], String [4096], TimeString [32], VmsTimeString [32]; static $DESCRIPTOR (BytesStringDsc, BytesString); static $DESCRIPTOR (ClientPortDsc, ClientPort); static $DESCRIPTOR (ElapsedDsc, Elapsed); static $DESCRIPTOR (HourlyStringDsc, HourlyString); static $DESCRIPTOR (StatusStringDsc, StatusString); static $DESCRIPTOR (StringDsc, String); static $DESCRIPTOR (TimeStringDsc, TimeString); static $DESCRIPTOR (VmsTimeStringDsc, VmsTimeString); static struct FAB LogFileFab; static struct RAB LogFileRab; static REQUEST_STRUCT DummyRequest; static VMS_ITEM_LIST3 LnmItems [] = { { sizeof(LoggingFileName)-1, LNM$_STRING, LoggingFileName, &Length }, { 0,0,0,0 } }; BOOL PeriodChanged; int status, SetimrStatus; unsigned long *vecptr, *BinTimePtr; unsigned short *NumTimePtr; unsigned long FaoVector [MAX_FAO_VECTOR]; char *aptr, *cptr, *sptr, *zptr, *FunctionNamePtr; char MiscChars [MAX_FAO_VECTOR * 2], ClientCertSubject [512]; /*********/ /* begin */ /*********/ if (WATCHING(rqptr) && WATCH_MODULE(WATCH_MOD__OTHER)) WatchThis (rqptr, FI_LI, WATCH_MOD__OTHER, "LoggingDo() !UL !&X !&X", Function, rqptr, svptr); /* logging to SYS$OUTPUT does not do many of the things that set 'status' */ status = SS$_NORMAL; if (Function == LOGGING_BEGIN) { /*****************/ /* begin logging */ /*****************/ /* if no logging file name from command line then use any config one */ if (!LoggingFileName[0] && Config.cfLog.FileName[0]) strcpy (LoggingFileName, Config.cfLog.FileName); if (!LoggingFileName[0]) { status = sys$trnlnm (0, &LnmFileDevDsc, &WasdLogNameDsc, 0, &LnmItems); if (VMSnok (status)) { status = sys$trnlnm (0, &LnmFileDevDsc, &HttpdLogNameDsc, 0, &LnmItems); if (VMSnok (status)) return (status); } LoggingFileName[Length] = '\0'; } if (!LoggingFileNameLength) LoggingFileNameLength = strlen(LoggingFileName); if (strsame (LoggingFileName, "SYS$OUTPUT", -1)) LoggingSysOutput = true; else LoggingSysOutput = false; if (Config.cfLog.ExtendBlocks) ExtendBlocks = Config.cfLog.ExtendBlocks; if (ExtendBlocks < 0) ExtendBlocks = 0; else if (ExtendBlocks > 65535) ExtendBlocks = 65535; /************************/ /* determine log format */ /************************/ svptr->LogFormatProblem = false; if (LoggingFormatUser[0]) svptr->LogFormatPtr = LoggingFormatUser; else if (svptr->LogFormat[0]) svptr->LogFormatPtr = svptr->LogFormat; else if (Config.cfLog.Format[0]) svptr->LogFormatPtr = Config.cfLog.Format; else svptr->LogFormatPtr = NULL; if (svptr->LogFormatPtr) { if (strsame (svptr->LogFormatPtr, "COMMON", -1)) { svptr->LogFormatCommonServer = svptr->LogFormatCombined = false; svptr->LogFormatCommon = true; svptr->LogFormatPtr = NULL; } else if (strsame (svptr->LogFormatPtr, "COMMON_SERVER", -1)) { svptr->LogFormatCommon = svptr->LogFormatCombined = false; svptr->LogFormatCommonServer = true; svptr->LogFormatPtr = NULL; } else if (strsame (svptr->LogFormatPtr, "COMBINED", -1)) { svptr->LogFormatCommon = svptr->LogFormatCommonServer = false; svptr->LogFormatCombined = true; svptr->LogFormatPtr = NULL; } else { svptr->LogFormatCommon = svptr->LogFormatCommonServer = svptr->LogFormatCombined = false; if (strstr (svptr->LogFormatPtr, "!PP")) LoggingProxyLocalPort = true; } } else svptr->LogFormatCommon = true; /****************************/ /* determine logging period */ /****************************/ LoggingPerPeriod = LoggingPeriodHourly = LoggingPeriodDaily = LoggingPeriodWeekly = LoggingPeriodMonthly = false; if (!LoggingPeriodName[0] && Config.cfLog.Period[0]) strcpy (LoggingPeriodName, Config.cfLog.Period); if (LoggingPeriodName[0]) { svptr->LogDayNumber = svptr->LogMonthNumber = svptr->LogYearNumber = 0; if (strsame (LoggingPeriodName, "HOURLY", 3)) LoggingPerPeriod = LoggingPeriodHourly = true; else if (strsame (LoggingPeriodName, "DAILY", 3)) LoggingPerPeriod = LoggingPeriodDaily = true; else if (strsame (LoggingPeriodName, "SUNDAY", 3)) { LoggingPerPeriod = LoggingPeriodWeekly = true; LoggingDayWeekBegins = 7; } else if (strsame (LoggingPeriodName, "WEEKLY", 3) || strsame (LoggingPeriodName, "MONDAY", 4)) { LoggingPerPeriod = LoggingPeriodWeekly = true; LoggingDayWeekBegins = 1; } else if (strsame (LoggingPeriodName, "TUESDAY", 3)) { LoggingPerPeriod = LoggingPeriodWeekly = true; LoggingDayWeekBegins = 2; } else if (strsame (LoggingPeriodName, "WEDNESDAY", 3)) { LoggingPerPeriod = LoggingPeriodWeekly = true; LoggingDayWeekBegins = 3; } else if (strsame (LoggingPeriodName, "THURSDAY", 3)) { LoggingPerPeriod = LoggingPeriodWeekly = true; LoggingDayWeekBegins = 4; } else if (strsame (LoggingPeriodName, "FRIDAY", 3)) { LoggingPerPeriod = LoggingPeriodWeekly = true; LoggingDayWeekBegins = 5; } else if (strsame (LoggingPeriodName, "SATURDAY", 3)) { LoggingPerPeriod = LoggingPeriodWeekly = true; LoggingDayWeekBegins = 6; } else if (strsame (LoggingPeriodName, "MONTH", 4)) LoggingPerPeriod = LoggingPeriodMonthly = true; else { FaoToStdout ("%HTTPD-W-LOG, period unknown\n \\!AZ\\\n", LoggingPeriodName); LoggingPerPeriod = false; } } /*************************/ /* get logging host name */ /*************************/ zptr = (sptr = svptr->LogHostName) + sizeof(svptr->LogHostName)-1; if (LoggingNaming == LOGGING_NAMING_ADDRESS) { /* as much of the IP address as possible */ for (cptr = svptr->ServerIpAddressString; *cptr && sptr < zptr; cptr++) { if (*cptr == '[' || *cptr == ']') continue; if (*cptr == '.' || *cptr == ':') *sptr++ = '-'; else *sptr++ = *cptr; } } else if (LoggingNaming == LOGGING_NAMING_HOST) { /* as much of the IP host name as possible */ for (cptr = svptr->ServerHostName; *cptr && sptr < zptr; cptr++) { if (*cptr == '[' || *cptr == ']') continue; if (*cptr == '.' || *cptr == ':') *sptr++ = '-'; else *sptr++ = *cptr; } } else { /* default, LOGGING_NAMING_NAME */ if (svptr->ServerHostName[0] == '[') for (cptr = svptr->ServerHostName; *cptr && (*cptr == '[' || *cptr == ']' || *cptr == ':' || isxdigit(*cptr)); cptr++); else for (cptr = svptr->ServerHostName; *cptr && (*cptr == '.' || isdigit(*cptr)); cptr++); if (*cptr) { /* the first part of the host name */ for (cptr = svptr->ServerHostName; *cptr && *cptr != '.' && sptr < zptr; *sptr++ = TOUP(*cptr++)); } else { /* all numeric/IPv6 service name */ for (cptr = svptr->ServerHostName; *cptr && sptr < zptr; cptr++) { if (*cptr == '[' || *cptr == ']') continue; if (*cptr == '.' || *cptr == ':') *sptr++ = '-'; else *sptr++ = *cptr; } } } *sptr = '\0'; zptr = (sptr = ProcessName) + sizeof(ProcessName)-1; for (cptr = HttpdProcess.PrcNam; *cptr && sptr < zptr; cptr++) if (!isalnum(*cptr)) *sptr++ = '-'; else *sptr++ = TOUP(*cptr); *sptr = '\0'; if (!LoggingEnabled) return (SS$_NORMAL); } if (Function == LOGGING_FLUSH) { /******************/ /* flush log file */ /******************/ if (LoggingSysOutput) return (SS$_NORMAL); if (!svptr->LogFileOpen) return (SS$_NORMAL); if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "FLUSH !AZ", svptr->LogFileName); sys$flush (&svptr->LogFileRab, 0, 0); return (SS$_NORMAL); } if (Function == LOGGING_SHUT) { /*****************/ /* shut log file */ /*****************/ if (LoggingSysOutput) return (SS$_NORMAL); if (!svptr->LogFileOpen) return (SS$_NORMAL); if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "SHUT !AZ", svptr->LogFileName); sys$close (&svptr->LogFileFab, 0, 0); svptr->LogFileOpen = false; return (SS$_NORMAL); } /*************************/ /* log file name change? */ /*************************/ if (rqptr) { /* use the request's times */ BinTimePtr = &rqptr->rqTime.Vms64bit; NumTimePtr = &rqptr->rqTime.VmsVector; } else { /* use the server's times */ BinTimePtr = &HttpdBinTime; NumTimePtr = &HttpdNumTime; } if (LoggingPerPeriod && (NumTimePtr[3] != svptr->LogHourNumber || NumTimePtr[2] != svptr->LogDayNumber || NumTimePtr[1] != svptr->LogMonthNumber || NumTimePtr[0] != svptr->LogYearNumber)) { PeriodChanged = false; if (LoggingPeriodHourly) { PeriodChanged = true; svptr->LogYearNumber = NumTimePtr[0]; svptr->LogMonthNumber = NumTimePtr[1]; svptr->LogDayNumber = NumTimePtr[2]; svptr->LogHourNumber = NumTimePtr[3]; } else if (LoggingPeriodDaily) { if (NumTimePtr[2] != svptr->LogDayNumber || NumTimePtr[1] != svptr->LogMonthNumber) { PeriodChanged = true; svptr->LogYearNumber = NumTimePtr[0]; svptr->LogMonthNumber = NumTimePtr[1]; svptr->LogDayNumber = NumTimePtr[2]; svptr->LogHourNumber = NumTimePtr[3]; } } else if (LoggingPeriodWeekly) { LoggingWeek (BinTimePtr, NumTimePtr, &WeeklyNumTime); if (WeeklyNumTime[0] != svptr->LogYearNumber || WeeklyNumTime[1] != svptr->LogMonthNumber || WeeklyNumTime[2] != svptr->LogDayNumber) { PeriodChanged = true; svptr->LogYearNumber = WeeklyNumTime[0]; svptr->LogMonthNumber = WeeklyNumTime[1]; svptr->LogDayNumber = WeeklyNumTime[2]; svptr->LogHourNumber = WeeklyNumTime[3]; } } else if (LoggingPeriodMonthly) { if (NumTimePtr[1] != svptr->LogMonthNumber) { PeriodChanged = true; svptr->LogYearNumber = NumTimePtr[0]; svptr->LogMonthNumber = NumTimePtr[1]; svptr->LogDayNumber = NumTimePtr[2]; svptr->LogHourNumber = NumTimePtr[3]; } } else ErrorExitVmsStatus (SS$_BUGCHECK, ErrorSanityCheck, FI_LI); if (PeriodChanged) { if (svptr->LogFileOpen) { sys$close (&svptr->LogFileFab, 0, 0); svptr->LogFileOpen = false; } svptr->LogFileNameLength = 0; svptr->LogFileName[0] = '\0'; } } if (!svptr->LogFileOpen && !LoggingSysOutput) { /*********************/ /* open the log file */ /*********************/ /* initialize the FAB before setting up the file name! */ svptr->LogFileFab = cc$rms_fab; if (LoggingPerPeriod) { /*************************************************/ /* per-period logging (with/without per-service) */ /*************************************************/ if (!svptr->LogFileNameLength) { vecptr = FaoVector; Length = strlen(svptr->LogHostName); /* basically no constraint on ODS-5 */ if (OdsVolumeStructure (LoggingFileName) != 5) { /* host name component can be from 17 to 20, or 23 chars max */ if (Config.cfLog.PerServiceHostOnly) { if (Length > 23) Length = 23; } else { if (Length + strlen(svptr->ServerPortString) > 22) Length = 22 - strlen(svptr->ServerPortString); } if (LoggingPeriodHourly) Length -= 2; } *vecptr++ = Length; *vecptr++ = svptr->LogHostName; if (Config.cfLog.PerServiceHostOnly) { *vecptr++ = ""; *vecptr++ = ""; } else { *vecptr++ = "_"; *vecptr++ = svptr->ServerPortString; } if (LoggingPeriodWeekly) { *vecptr++ = WeeklyNumTime[0]; *vecptr++ = WeeklyNumTime[1]; *vecptr++ = WeeklyNumTime[2]; } else { *vecptr++ = NumTimePtr[0]; *vecptr++ = NumTimePtr[1]; if (LoggingPeriodMonthly) *vecptr++ = 1; else *vecptr++ = NumTimePtr[2]; } if (LoggingPeriodHourly) { sys$fao (&HourlyFaoDsc, 0, &HourlyStringDsc, NumTimePtr[3]); *vecptr++ = HourlyString; } else *vecptr++ = ""; if (Config.cfLog.PerInstance) { *vecptr++ = "_"; *vecptr++ = SysInfo.NodeName; *vecptr++ = "_"; *vecptr++ = ProcessName; } else { *vecptr++ = ""; *vecptr++ = ""; *vecptr++ = ""; *vecptr++ = ""; } svptr->LogFileNameDsc.dsc$a_pointer = svptr->LogFileName; svptr->LogFileNameDsc.dsc$w_length = sizeof(svptr->LogFileName)-1; status = sys$faol (&PeriodFileNameFaoDsc, &svptr->LogFileNameLength, &svptr->LogFileNameDsc, &FaoVector); if (VMSnok (status)) ErrorExitVmsStatus (status, NULL, FI_LI); svptr->LogFileName[svptr->LogFileNameLength] = '\0'; } /* logging file name is used for the directory component only */ svptr->LogFileFab.fab$l_dna = LoggingFileName; svptr->LogFileFab.fab$b_dns = LoggingFileNameLength; svptr->LogFileFab.fab$l_fna = svptr->LogFileName; svptr->LogFileFab.fab$b_fns = svptr->LogFileNameLength; } else if (LoggingNaming) { /***************************************/ /* per-service logging (no per-period) */ /***************************************/ if (!svptr->LogFileNameLength) { vecptr = FaoVector; Length = strlen(svptr->LogHostName); /* basically no constraint on ODS-5 */ if (OdsVolumeStructure (LoggingFileName) != 5) { /* host name component can be from 26 to 29, or 32 chars max */ if (Config.cfLog.PerServiceHostOnly) { if (Length > 32) Length = 32; } else { if (Length + strlen(svptr->ServerPortString) > 31) Length = 31 - strlen(svptr->ServerPortString); } } *vecptr++ = Length; *vecptr++ = svptr->LogHostName; if (Config.cfLog.PerServiceHostOnly) { *vecptr++ = ""; *vecptr++ = ""; } else { *vecptr++ = "_"; *vecptr++ = svptr->ServerPortString; } if (Config.cfLog.PerInstance) { *vecptr++ = "_"; *vecptr++ = SysInfo.NodeName; *vecptr++ = "_"; *vecptr++ = ProcessName; } else { *vecptr++ = ""; *vecptr++ = ""; *vecptr++ = ""; *vecptr++ = ""; } svptr->LogFileNameDsc.dsc$a_pointer = svptr->LogFileName; svptr->LogFileNameDsc.dsc$w_length = sizeof(svptr->LogFileName)-1; status = sys$faol (&ServiceFileNameFaoDsc, &svptr->LogFileNameLength, &svptr->LogFileNameDsc, &FaoVector); if (VMSnok (status)) ErrorExitVmsStatus (status, NULL, FI_LI); svptr->LogFileName[svptr->LogFileNameLength] = '\0'; } /* logging file name is used for the directory component only */ svptr->LogFileFab.fab$l_dna = LoggingFileName; svptr->LogFileFab.fab$b_dns = LoggingFileNameLength; svptr->LogFileFab.fab$l_fna = svptr->LogFileName; svptr->LogFileFab.fab$b_fns = svptr->LogFileNameLength; } else { /******************/ /* fixed log file */ /******************/ /* the logging file name must be complete */ svptr->LogFileFab.fab$l_fna = LoggingFileName; svptr->LogFileFab.fab$b_fns = LoggingFileNameLength; } /************************/ /* create/open log file */ /************************/ if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "OPEN !AZ", svptr->LogFileName); svptr->LogFileFab.fab$l_fop = FAB$M_CIF | FAB$M_DFW | FAB$M_SQO | FAB$M_TEF; svptr->LogFileFab.fab$w_deq = ExtendBlocks; svptr->LogFileFab.fab$b_fac = FAB$M_PUT; svptr->LogFileFab.fab$b_rfm = FAB$C_STMLF; svptr->LogFileFab.fab$b_shr = FAB$M_SHRGET | FAB$M_SHRPUT | FAB$M_SHRUPD; svptr->LogFileFab.fab$b_org = FAB$C_SEQ; svptr->LogFileFab.fab$b_rat = FAB$M_CR; /* turn on SYSPRV to allow access to the logging file */ sys$setprv (1, &SysPrvMask, 0, 0); status = sys$create (&svptr->LogFileFab, 0, 0); sys$setprv (0, &SysPrvMask, 0, 0); if (VMSnok (status)) { if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "CREATE !AZ !&S", svptr->LogFileName, status); if (!svptr->LogFileError) { svptr->LogFileError = LoggingFileError = true; FaoToStdout ("%HTTPD-W-LOG, file create error\n-!&M\n \\!AZ\\\n", status, svptr->LogFileName); if (Config.cfLog.WriteFail503) LoggingFileError = true; } return (status); } svptr->LogFileError = LoggingFileError = false; svptr->LogFileRab = cc$rms_rab; svptr->LogFileRab.rab$l_fab = &svptr->LogFileFab; svptr->LogFileRab.rab$b_mbc = 127; svptr->LogFileRab.rab$b_mbf = 4; svptr->LogFileRab.rab$l_rop = RAB$M_EOF | RAB$M_WBH; if (VMSnok (status = sys$connect (&svptr->LogFileRab, 0, 0))) { if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "CREATE !AZ !&S", svptr->LogFileName, status); sys$close (&svptr->LogFileFab, 0, 0); return (status); } svptr->LogFileOpen = true; } /***********************/ /* act on the log file */ /***********************/ status = sys$fao (&LogFileTimeFaoDsc, &Length, &TimeStringDsc, NumTimePtr[2], MonthName[NumTimePtr[1]], NumTimePtr[0], NumTimePtr[3], NumTimePtr[4], NumTimePtr[5], TimeGmtString, TimeGmtString+4); TimeString[Length] = '\0'; if (Function == LOGGING_BEGIN || Function == LOGGING_CLOSE || Function == LOGGING_END || Function == LOGGING_OPEN || Function == LOGGING_SHUT || Function == LOGGING_TIMESTAMP) { switch (Function) { case LOGGING_BEGIN : FunctionNamePtr = "BEGIN"; break; case LOGGING_CLOSE : FunctionNamePtr = "CLOSE"; break; case LOGGING_END : FunctionNamePtr = "END"; break; case LOGGING_OPEN : FunctionNamePtr = "OPEN"; break; case LOGGING_SHUT : FunctionNamePtr = "SHUT"; break; case LOGGING_TIMESTAMP : FunctionNamePtr = "TIMESTAMP"; break; default : FunctionNamePtr = "*ERROR*"; } if (svptr->LogFormatCommon || svptr->LogFormatCommonServer || svptr->LogFormatCombined) { vecptr = FaoVector; *vecptr++ = ServerHostName; *vecptr++ = "-"; *vecptr++ = HttpdProcess.UserName; *vecptr++ = TimeString; *vecptr++ = SysInfo.NodeName; *vecptr++ = HttpdProcess.PrcNam; *vecptr++ = FunctionNamePtr; if (Function == LOGGING_TIMESTAMP) *vecptr++ = LoggingTimeStampCount; else *vecptr++ = ExitStatus; if (svptr->LogFormatCommonServer) { *vecptr++ = " \"-\" \"-\""; *vecptr++ = ""; *vecptr++ = ""; } else if (svptr->LogFormatCombined) { *vecptr++ = " \"-\" \""; *vecptr++ = SoftwareID; *vecptr++ = "\""; } else { *vecptr++ = ""; *vecptr++ = ""; *vecptr++ = ""; } if (Function == LOGGING_TIMESTAMP) status = sys$faol (&LogFileTimeStampFaoDsc, &Length, &StringDsc, &FaoVector); else status = sys$faol (&LogFilePseudoFaoDsc, &Length, &StringDsc, &FaoVector); if (VMSnok (status) || status == SS$_BUFFEROVF) ErrorExitVmsStatus (status, NULL, FI_LI); String[Length] = '\0'; if (WATCH_CAT && WatchThisOne) { WatchThis (rqptr, FI_LI, WATCH_LOG, "ENTRY !UL bytes", Length); WatchData (String, Length); } if (LoggingSysOutput) fprintf (stdout, "%s\n", String); else { svptr->LogFileRab.rab$l_rbf = String; svptr->LogFileRab.rab$w_rsz = Length; if (VMSnok (status = sys$put (&svptr->LogFileRab, 0, 0))) { if (!svptr->LogFileError) { svptr->LogFileError = LoggingFileError = true; FaoToStdout ("%HTTPD-W-LOG, \ file write error\n-!&M\n \\!AZ\\\n", status, svptr->LogFileName); } } else svptr->LogFileError = LoggingFileError = false; } } if (Function == LOGGING_END || Function == LOGGING_CLOSE) { /******************/ /* close log file */ /******************/ if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "CLOSE !AZ", svptr->LogFileName); if (LoggingSysOutput) return (SS$_NORMAL); sys$close (&svptr->LogFileFab, 0, 0); svptr->LogFileOpen = false; } if (Function != LOGGING_BEGIN) return (SS$_NORMAL); /***********************/ /* test logging format */ /***********************/ memset (&DummyRequest, 0, sizeof(DummyRequest)); rqptr = &DummyRequest; } if (!rqptr) return (SS$_NORMAL); /*************************/ /* format request record */ /*************************/ if (svptr->LogFormatPtr) { /***********************/ /* user-defined format */ /***********************/ int cnt; char *cptr, *sptr, *AbsentPtr; if (svptr->LogFormatProblem) return (SS$_NORMAL); cnt = 0; sptr = MiscChars; AbsentPtr = ""; cptr = svptr->LogFormatPtr; vecptr = FaoVector; while (*cptr) { if (cnt > MAX_FAO_VECTOR) ErrorExitVmsStatus (0, ErrorLoggingFormatLength, FI_LI); if (cnt == 1) AbsentPtr = FaoVector[0]; switch (*cptr) { case '!' : { cptr++; switch (*(USHORTPTR)cptr) { case 'AR' : if (!rqptr->rqAuth.RealmPtr) *vecptr++ = AbsentPtr; else if (!rqptr->rqAuth.RealmPtr[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqAuth.RealmPtr; cnt++; cptr += 2; continue; case 'AU' : if (!rqptr->RemoteUser[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->RemoteUser; cnt++; cptr += 2; continue; case 'BB' : if (QUAD_NOT_ZERO(rqptr->BytesRawTx)) { sys$fao (&BytesFaoDsc, 0, &BytesStringDsc, rqptr->BytesRawTx[1] ? 4294967295 : rqptr->BytesRawTx[0] - rqptr->rqResponse.HeaderLength); *vecptr++ = BytesString; } else *vecptr++ = "0"; cnt++; cptr += 2; continue; case 'BQ' : if (QUAD_NOT_ZERO(rqptr->BytesRawTx)) { sys$fao (&QuadBytesFaoDsc, 0, &BytesStringDsc, &rqptr->BytesRawTx); *vecptr++ = BytesString; } else *vecptr++ = "0"; cnt++; cptr += 2; continue; case 'BY' : if (QUAD_NOT_ZERO(rqptr->BytesRawTx)) { sys$fao (&BytesFaoDsc, 0, &BytesStringDsc, rqptr->BytesRawTx[1] ? 4294967295 : rqptr->BytesRawTx[0]); *vecptr++ = BytesString; } else *vecptr++ = "0"; cnt++; cptr += 2; continue; case 'CA' : *vecptr++ = rqptr->rqClient.IpAddressString; cnt++; cptr += 2; continue; case 'CC' : /* replace all spaces with underscores */ if (rqptr->rqAuth.ClientCertSubjectPtr && rqptr->rqAuth.ClientCertSubjectPtr[0]) { zptr = (sptr = ClientCertSubject) + sizeof(ClientCertSubject)-1; for (cptr = rqptr->rqAuth.ClientCertSubjectPtr; *cptr && sptr < zptr; cptr++) { if (isspace(*cptr)) *sptr++ = '_'; else *sptr++ = *cptr; } *sptr = '\0'; *vecptr++ = ClientCertSubject; } else *vecptr++ = AbsentPtr; cnt++; cptr += 2; continue; case 'CI' : /* cache involvement removed 03-APR-2002 */ cptr += 2; continue; case 'CN' : *vecptr++ = rqptr->rqClient.Lookup.HostName; cnt++; cptr += 2; continue; case 'CP' : sys$fao (&ClientPortFaoDsc, 0, &ClientPortDsc, rqptr->rqClient.IpPort); *vecptr++ = ClientPort; cnt++; cptr += 2; continue; case 'EM' : { static char str [32]; double dsecs; dsecs = (double)(-(long)rqptr->rqResponse.Duration[0]) + (double)(-(long)rqptr->rqResponse.Duration[1]) * 4294967295.0; sprintf (str, "%u", (long)(dsecs / 1000.0)); *vecptr++ = str; cnt++; cptr += 2; continue; } case 'ES' : { static char str [32]; double dsecs; /** dsecs = (double)(-(long)rqptr->rqResponse.Duration[0]) + (double)(-(long)rqptr->rqResponse.Duration[1]) * 4294967295.0; **/ dsecs = (double)(-(long)rqptr->rqResponse.Duration[0]); #ifndef __VAX sprintf (str, "%.6f", dsecs / 10000000.0); #else sprintf (str, "%.3f", dsecs / 10000000.0); #endif *vecptr++ = str; cnt++; cptr += 2; continue; } case 'ET' : { static char str [32]; double dsecs; dsecs = (double)(-(long)rqptr->rqResponse.Duration[0]) + (double)(-(long)rqptr->rqResponse.Duration[1]) * 4294967295.0; sprintf (str, "%u", (long)(dsecs / 10000000.0)); *vecptr++ = str; cnt++; cptr += 2; continue; } case 'EU' : { static char str [32]; double dsecs; dsecs = (double)(-(long)rqptr->rqResponse.Duration[0]) + (double)(-(long)rqptr->rqResponse.Duration[1]) * 4294967295.0; sprintf (str, "%u", (long)(dsecs / 10.0)); *vecptr++ = str; cnt++; cptr += 2; continue; } case 'HO' : if (!rqptr->rqHeader.HostPtr) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqHeader.HostPtr; cnt++; cptr += 2; continue; case 'ID' : if (!rqptr->TrackId[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->TrackId; cnt++; cptr += 2; continue; case 'ME' : *vecptr++ = rqptr->rqHeader.MethodName; cnt++; cptr += 2; continue; case 'PA' : if (!rqptr->rqHeader.PathInfoPtr) *vecptr++ = AbsentPtr; else if (!rqptr->rqHeader.PathInfoPtr[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqHeader.PathInfoPtr; cnt++; cptr += 2; continue; case 'PP' : { static char str [16]; sprintf (str, "%d", rqptr->ProxyLocalPort); *vecptr++ = str; cnt++; cptr += 2; continue; } case 'PR' : switch (rqptr->rqHeader.HttpVersion) { case HTTP_VERSION_1_0 : *vecptr++ = " HTTP/1.0"; break; case HTTP_VERSION_1_1 : *vecptr++ = " HTTP/1.1"; break; default : *vecptr++ = AbsentPtr; } cnt++; cptr += 2; continue; case 'QS' : if (!rqptr->rqHeader.QueryStringLength) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqHeader.QueryStringPtr; cnt++; cptr += 2; continue; case 'RF' : if (!rqptr->rqHeader.RefererPtr) *vecptr++ = AbsentPtr; else if (!rqptr->rqHeader.RefererPtr[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqHeader.RefererPtr; cnt++; cptr += 2; continue; case 'RH' : if (aptr = LoggingRequestHeader (rqptr, cptr)) { if (*aptr) *vecptr++ = aptr; else *vecptr++ = AbsentPtr; cnt++; /* "RH:field-name:" (it's already been validated!) */ for (cptr += 3; *cptr && *cptr != ':'; cptr++); if (*cptr) cptr++; } else { svptr->LogFormatProblem = true; while (*cptr) cptr++; } continue; case 'RQ' : if (!rqptr->rqHeader.MethodName[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqHeader.MethodName; cnt++; *vecptr++ = " "; cnt++; if (!rqptr->rqHeader.RequestUriPtr) *vecptr++ = AbsentPtr; else if (!rqptr->rqHeader.RequestUriPtr[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqHeader.RequestUriPtr; cnt++; switch (rqptr->rqHeader.HttpVersion) { case HTTP_VERSION_1_0 : *vecptr++ = " HTTP/1.0"; cnt++; break; case HTTP_VERSION_1_1 : *vecptr++ = " HTTP/1.1"; cnt++; break; default : *vecptr++ = ""; cnt++; } cptr += 2; continue; case 'RS' : sys$fao (&StatusFaoDsc, 0, &StatusStringDsc, rqptr->rqResponse.HttpStatus); *vecptr++ = StatusString; cnt++; cptr += 2; continue; case 'SC' : if (!rqptr->ScriptName[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->ScriptName; cnt++; cptr += 2; continue; case 'SM' : /* must come from request's service pointer */ if (!rqptr || !rqptr->ServicePtr || !rqptr->ServicePtr->RequestSchemeNamePtr) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->ServicePtr->RequestSchemeNamePtr; cnt++; cptr += 2; continue; case 'SN' : /* must come from request's service pointer */ if (!rqptr || !rqptr->ServicePtr || !rqptr->ServicePtr->ServerHostName[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->ServicePtr->ServerHostName; cnt++; cptr += 2; continue; case 'SP' : /* must come from request's service pointer */ if (!rqptr || !rqptr->ServicePtr || !rqptr->ServicePtr->ServerPortString[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->ServicePtr->ServerPortString; cnt++; cptr += 2; continue; case 'TC' : *vecptr++ = TimeString; cnt++; cptr += 2; continue; case 'TG' : if (!rqptr->rqTime.GmDateTime[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqTime.GmDateTime; cnt++; cptr += 2; continue; case 'TV' : sys$fao (&VmsTimeFaoDsc, 0, &VmsTimeStringDsc, &rqptr->rqTime.Vms64bit); *vecptr++ = VmsTimeString; cnt++; cptr += 2; continue; case 'UA' : if (!rqptr->rqHeader.UserAgentPtr) *vecptr++ = AbsentPtr; else if (!rqptr->rqHeader.UserAgentPtr[0]) *vecptr++ = AbsentPtr; else *vecptr++ = rqptr->rqHeader.UserAgentPtr; cnt++; cptr += 2; continue; case 'VS' : *vecptr++ = rqptr->ServicePtr->ServerHostPort; cnt++; cptr += 2; continue; default : svptr->LogFormatProblem = true; while (*cptr) cptr++; continue; } } case '\\' : { cptr++; switch (*cptr) { case '0' : *vecptr++ = ""; cnt++; cptr++; continue; case 'n' : *vecptr++ = "\n"; cnt++; cptr++; continue; case 'q' : *vecptr++ = "\""; cnt++; cptr++; continue; case 't' : *vecptr++ = "\t"; cnt++; cptr++; continue; case '!' : *vecptr++ = "!"; cnt++; cptr++; continue; case '\\' : *vecptr++ = "\\"; cnt++; cptr++; continue; default : svptr->LogFormatProblem = true; while (*cptr) cptr++; continue; } } default : { *sptr = *cptr++; *vecptr++ = sptr++; *sptr++ = '\0'; cnt++; continue; } } } /* now set [0] to the repeat count */ FaoVector[0] = cnt - 1; if (cnt <= 1) svptr->LogFormatProblem = true; if (svptr->LogFormatProblem) { MetaConReport (MetaGlobalServicePtr, METACON_REPORT_ERROR, "Log format problem with !AZ!AZ\n\\!AZ\\", svptr->RequestSchemeNamePtr, svptr->ServerHostPort, svptr->LogFormatPtr); FaoToStdout ("%HTTPD-W-LOG, format problem\n \\!AZ\\\n", svptr->LogFormatPtr); /* fall-back to providing a common-format log */ svptr->LogFormatCommon = true; svptr->LogFormatPtr = NULL; FaoToStdout ("-HTTPD-I-LOG, fall-back to COMMON log format\n"); } } if (svptr->LogFormatCommon || svptr->LogFormatCommonServer || svptr->LogFormatCombined) { /*******************/ /* common/combined */ /*******************/ vecptr = FaoVector; *vecptr++ = rqptr->rqClient.Lookup.HostName; /* X509 client cert auth (replace all spaces with underscores) */ if (rqptr->rqAuth.ClientCertSubjectPtr && rqptr->rqAuth.ClientCertSubjectPtr[0]) { zptr = (sptr = ClientCertSubject) + sizeof(ClientCertSubject)-1; for (cptr = rqptr->rqAuth.ClientCertSubjectPtr; *cptr && sptr < zptr; cptr++) { if (isspace(*cptr)) *sptr++ = '_'; else *sptr++ = *cptr; } *sptr = '\0'; *vecptr++ = ClientCertSubject; } else /* if tracking is not in use or none applies "place-mark" it */ if (rqptr->TrackId[0]) *vecptr++ = rqptr->TrackId; else *vecptr++ = "-"; /* if authentication has not been supplied "place-mark" remote user */ if (rqptr->RemoteUser[0]) *vecptr++ = rqptr->RemoteUser; else *vecptr++ = "-"; *vecptr++ = TimeString; if (rqptr->rqHeader.MethodName[0]) *vecptr++ = rqptr->rqHeader.MethodName; else *vecptr++ = "-"; if (!rqptr->rqHeader.RequestUriPtr || !rqptr->rqHeader.RequestUriPtr[0]) *vecptr++ = "-"; else *vecptr++ = rqptr->rqHeader.RequestUriPtr; switch (rqptr->rqHeader.HttpVersion) { case HTTP_VERSION_1_0 : *vecptr++ = " HTTP/1.0"; break; case HTTP_VERSION_1_1 : *vecptr++ = " HTTP/1.1"; break; default : *vecptr++ = ""; } *vecptr++ = rqptr->rqResponse.HttpStatus; if (QUAD_NOT_ZERO(rqptr->BytesRawTx)) { /* suspect the maximum of log analysis tools will be a longword! */ sys$fao (&BytesFaoDsc, &Length, &BytesStringDsc, rqptr->BytesRawTx[1] ? 4294967295 : rqptr->BytesRawTx[0]); *vecptr++ = BytesString; } else *vecptr++ = "0"; if (svptr->LogFormatCommonServer) *vecptr++ = rqptr->ServicePtr->ServerHostName; else if (svptr->LogFormatCombined) { if (!rqptr->rqHeader.RefererPtr || !rqptr->rqHeader.RefererPtr[0]) *vecptr++ = "-"; else *vecptr++ = rqptr->rqHeader.RefererPtr; if (!rqptr->rqHeader.UserAgentPtr || !rqptr->rqHeader.UserAgentPtr[0]) *vecptr++ = "-"; else *vecptr++ = rqptr->rqHeader.UserAgentPtr; } } else if (!svptr->LogFormatPtr) ErrorExitVmsStatus (SS$_BUGCHECK, ErrorSanityCheck, FI_LI); /*************/ /* sys$fao() */ /*************/ if (svptr->LogFormatCommon) status = sys$faol (&LogFileCommonFaoDsc, &Length, &StringDsc, &FaoVector); else if (svptr->LogFormatCombined) status = sys$faol (&LogFileCombinedFaoDsc, &Length, &StringDsc, &FaoVector); else if (svptr->LogFormatCommonServer) status = sys$faol (&LogFileCommonServerFaoDsc, &Length, &StringDsc, &FaoVector); else if (svptr->LogFormatPtr) status = sys$faol (&LogFileUserFaoDsc, &Length, &StringDsc, &FaoVector); else ErrorExitVmsStatus (SS$_BUGCHECK, ErrorSanityCheck, FI_LI); if (VMSnok (status) || status == SS$_BUFFEROVF) ErrorNoticed (rqptr, status, NULL, FI_LI); String[Length] = '\0'; /**********************************/ /* if only testing the log format */ /**********************************/ if (rqptr == &DummyRequest) return (SS$_NORMAL); /********************/ /* write the record */ /********************/ if (WATCH_CAT && WatchThisOne) { if (LoggingPerService) { WatchThis (rqptr, FI_LI, WATCH_LOG, "ENTRY !AZ !UL bytes", svptr->LogFileName, Length); WatchData (String, Length); } else { WatchThis (rqptr, FI_LI, WATCH_LOG, "ENTRY !UL bytes", Length); WatchData (String, Length); } } if (LoggingSysOutput) { fprintf (stdout, "%s\n", String); status = SS$_NORMAL; } else { svptr->LogFileRab.rab$l_rbf = String; svptr->LogFileRab.rab$w_rsz = Length; if (VMSnok (status = sys$put (&svptr->LogFileRab, 0, 0))) { if (WATCH_CAT && WatchThisOne) WatchThis (rqptr, FI_LI, WATCH_LOG, "PUT !AZ !&S", svptr->LogFileName, status); if (!svptr->LogFileError) { svptr->LogFileError = LoggingFileError = true; FaoToStdout ("%HTTPD-W-LOG, file write error\n-!&M\n \\!AZ\\\n", status, svptr->LogFileName); } } else svptr->LogFileError = LoggingFileError = false; } return (status); } /*****************************************************************************/ /* "RH:field-name:" returns a pointer to the start of the specified field name value, or pointer to an empty string if not found, or NULL if a directive format error was detected. This is a reasonably expensive search and logging directive! */ char* LoggingRequestHeader ( REQUEST_STRUCT *rqptr, char *DirectivePtr ) { int rfidx, NameLength; char *cptr, *sptr, *zptr; char **rfptr; char FieldName [256]; /*********/ /* begin */ /*********/ if (WATCH_MODULE(WATCH_MOD__OTHER)) WatchThis (NULL, FI_LI, WATCH_MOD__OTHER, "LoggingRequestHeader()"); cptr = DirectivePtr + 2; if (*cptr != ':') return (NULL); zptr = (sptr = FieldName) + sizeof(FieldName)-1; for (cptr++; *cptr && *cptr != ':' && sptr < zptr; *sptr++ = TOUP(*cptr++)); if (*cptr != ':') return (NULL); *sptr = '\0'; NameLength = sptr - FieldName; rfptr = &rqptr->rqHeader.RequestFieldsPtr; for (rfidx = 0; rfidx < rqptr->rqHeader.RequestFieldsCount; rfidx++) { if (TOUP(rfptr[rfidx][0]) == FieldName[0] && TOUP(rfptr[rfidx][NameLength-1]) == FieldName[NameLength-1] && TOUP(rfptr[rfidx][NameLength] == ':' && strsame (rfptr[rfidx], FieldName, NameLength))) { /* hit! */ for (cptr = rfptr[rfidx] + NameLength + 1; *cptr && ISLWS(*cptr); cptr++); return (cptr); } } /* not found */ return (""); } /*****************************************************************************/ /* Fills 'WeeklyNumTimePtr' with the date of the most recent 'LoggingDayWeekBegins' (i.e. the last Monday, Tuesday ... Sunday) */ LoggingWeek ( unsigned long *BinTimePtr, unsigned short *NumTimePtr, unsigned short *WeeklyNumTimePtr ) { static unsigned long DeltaDaysBinaryTime [2], ResultBinaryTime [2]; static $DESCRIPTOR (DeltaDaysFaoDsc, "!UL 00:00:00.00"); int status, DeltaDays; unsigned short Length; char DeltaString [32]; $DESCRIPTOR (DeltaStringDsc, DeltaString); /*********/ /* begin */ /*********/ if (WATCH_MODULE(WATCH_MOD__OTHER)) WatchThis (NULL, FI_LI, WATCH_MOD__OTHER, "LoggingWeek()"); /* monday == 1, tuesday == 2 ... sunday == 7 */ if ((DeltaDays = HttpdDayOfWeek - LoggingDayWeekBegins) < 0) DeltaDays += 7; if (!DeltaDays) { /* same bat-time, same bat-channel */ memcpy (WeeklyNumTimePtr, NumTimePtr, 14); return; } status = sys$fao (&DeltaDaysFaoDsc, &Length, &DeltaStringDsc, DeltaDays); if (VMSnok (status)) ErrorExitVmsStatus (status, NULL, FI_LI); DeltaStringDsc.dsc$w_length = Length; status = sys$bintim (&DeltaStringDsc, DeltaDaysBinaryTime); if (VMSnok (status)) ErrorExitVmsStatus (status, NULL, FI_LI); status = lib$sub_times (BinTimePtr, &DeltaDaysBinaryTime, &ResultBinaryTime); if (VMSnok (status)) ErrorExitVmsStatus (status, NULL, FI_LI); /* overwrite the supplied numeric time with the start of week's */ sys$numtim (WeeklyNumTimePtr, &ResultBinaryTime); } /*****************************************************************************/ /* Return a plain text report comprising access records in the last 65kBytes (maximum) of the log associated with the specified service. Not asynchronous but fast (and convenient) enough not to introduce too much granularity. */ LoggingReport ( REQUEST_STRUCT *rqptr, REQUEST_AST NextTaskFunction, char *ServerHostPort ) { int cnt, status, BufferBlockCount; char *cptr, *zptr, *BufferPtr; struct FAB LogFileFab; struct RAB LogFileRab; struct XABFHC LogFileXabFhc; SERVICE_STRUCT *svptr; /*********/ /* begin */ /*********/ if (WATCH_MODULE(WATCH_MOD__OTHER)) WatchThis (NULL, FI_LI, WATCH_MOD__OTHER, "LoggingReport() !&A !&Z", NextTaskFunction, ServerHostPort); for (svptr = ServiceListHead; svptr; svptr = svptr->NextPtr) if (strsame (svptr->ServerHostPort, ServerHostPort, -1)) break; if (!svptr) { rqptr->rqResponse.HttpStatus = 404; ErrorGeneral (rqptr, "Service not found.", FI_LI); SysDclAst (NextTaskFunction, rqptr); return; } if (!LoggingPerService) svptr = ServiceListHead; if (!svptr->LogFileNameLength) { rqptr->rqResponse.HttpStatus = 404; ErrorGeneral (rqptr, "Log file not defined.", FI_LI); SysDclAst (NextTaskFunction, rqptr); return; } /* make sure we get all the latest access records */ if (svptr->LogFileOpen) sys$flush (&svptr->LogFileRab, 0, 0); LogFileFab = cc$rms_fab; LogFileFab.fab$l_dna = LoggingFileName; LogFileFab.fab$b_dns = LoggingFileNameLength; LogFileFab.fab$l_fna = svptr->LogFileName; LogFileFab.fab$b_fns = svptr->LogFileNameLength; LogFileFab.fab$b_fac = FAB$M_GET | FAB$M_BIO; LogFileFab.fab$b_shr = FAB$M_SHRGET | FAB$M_SHRPUT | FAB$M_UPI; LogFileFab.fab$l_xab = &LogFileXabFhc; LogFileXabFhc = cc$rms_xabfhc; sys$setprv (1, &SysPrvMask, 0, 0); status = sys$open (&LogFileFab, 0, 0); sys$setprv (0, &SysPrvMask, 0, 0); if (VMSok (status)) status = LogFileFab.fab$l_sts; if (VMSnok (status)) { rqptr->rqResponse.ErrorTextPtr = svptr->LogFileName; ErrorVmsStatus (rqptr, status, FI_LI); SysDclAst (NextTaskFunction, rqptr); return; } if (LogFileXabFhc.xab$l_ebk > 127) BufferBlockCount = 127; else BufferBlockCount = LogFileXabFhc.xab$l_ebk; BufferPtr = VmGetHeap (rqptr, BufferBlockCount * 512); LogFileRab = cc$rms_rab; if (BufferBlockCount >= LogFileXabFhc.xab$l_ebk) LogFileRab.rab$l_bkt = 1; else LogFileRab.rab$l_bkt = LogFileXabFhc.xab$l_ebk - BufferBlockCount + 1; LogFileRab.rab$l_fab = &LogFileFab; LogFileRab.rab$l_rop = RAB$M_BIO; LogFileRab.rab$l_ubf = BufferPtr; LogFileRab.rab$w_usz = BufferBlockCount * 512; if (WATCH_MODULE(WATCH_MOD__OTHER)) WatchThis (NULL, FI_LI, WATCH_MOD__OTHER, "XABFHC ebk:!UL ffb:!UL bkt:!UL usz:!UL", LogFileXabFhc.xab$l_ebk, LogFileXabFhc.xab$w_ffb, LogFileRab.rab$l_bkt, LogFileRab.rab$w_usz); status = sys$connect (&LogFileRab, 0, 0); if (VMSok (status)) status = LogFileRab.rab$l_sts; if (VMSnok (status)) { rqptr->rqResponse.ErrorTextPtr = svptr->LogFileName; ErrorVmsStatus (rqptr, status, FI_LI); sys$close (&LogFileFab, 0, 0); SysDclAst (NextTaskFunction, rqptr); return; } status = sys$read (&LogFileRab, 0, 0); if (VMSok (status)) status = LogFileRab.rab$l_sts; if (status == RMS$_EOF) status = SS$_NORMAL; if (VMSnok (status)) { rqptr->rqResponse.ErrorTextPtr = svptr->LogFileName; ErrorVmsStatus (rqptr, status, FI_LI); sys$close (&LogFileFab, 0, 0); SysDclAst (NextTaskFunction, rqptr); return; } status = sys$close (&LogFileFab, 0, 0); if (VMSok (status)) status = LogFileFab.fab$l_sts; if (VMSnok (status)) { rqptr->rqResponse.ErrorTextPtr = svptr->LogFileName; ErrorVmsStatus (rqptr, status, FI_LI); SysDclAst (NextTaskFunction, rqptr); return; } /* whole records only (quite likely to straddle a block boundary) */ zptr = (cptr = BufferPtr) + LogFileRab.rab$w_rsz; while (cptr < zptr && *cptr != '\n') cptr++; cptr++; /* if empty or only the one record */ if (cptr >= zptr) cptr = BufferPtr; cnt = LogFileRab.rab$w_rsz - (cptr - BufferPtr); rqptr->rqResponse.PreExpired = PRE_EXPIRE_ADMIN; ResponseHeader200 (rqptr, "text/plain", NULL); if (cnt) NetWrite (rqptr, NextTaskFunction, cptr, cnt); else SysDclAst (NextTaskFunction, rqptr); } /*****************************************************************************/