Windows: improved idle dead time handling
[openafs.git] / src / WINNT / afsd / afsd_eventlog.c
1 ////////////////////////////////////////////////////////////////////
2 //
3 //
4 //              E V E N T   L O G G I N G   F U N C T I O N S
5 //
6 //
7 ////////////////////////////////////////////////////////////////////
8
9
10 #include <afsconfig.h>
11 #include <afs/param.h>
12 #include <roken.h>
13
14 #include <windows.h>
15 #include <stdarg.h>
16 #include <string.h>
17 #include <strsafe.h>
18 #include <WINNT/afsreg.h>
19 #include "afsd.h"
20 #include "afsd_eventlog.h"
21 #define AFS_VERSION_STRINGS
22 #include "afs_component_version_number.h"
23
24 static BOOL     GetServicePath(LPTSTR lpPathBuf, PDWORD pdwPathBufSize);
25 static BOOL     AddEventSource(void);
26
27 static BOOL
28 GetServicePath(LPTSTR lpPathBuf, PDWORD pdwPathBufSize)
29 {
30     HKEY        hKey = NULL;
31     DWORD       dwData = 0;
32     BOOL        bRet = TRUE;
33
34     do {
35         // Open key
36         if ( RegOpenKeyEx( HKEY_LOCAL_MACHINE, AFSREG_CLT_SVC_SUBKEY, 0, KEY_QUERY_VALUE, &hKey ) )
37         {
38             bRet = FALSE;
39             break;
40         }
41
42         // prepare user's buffer and read into it
43         dwData = *pdwPathBufSize;
44         memset(lpPathBuf, '\0', dwData);
45         if ( RegQueryValueEx( hKey,                     // handle to key
46                               "ImagePath",              // value name
47                               NULL,                     // reserved
48                               NULL,                     // type buffer
49                               (LPBYTE) lpPathBuf,       // data buffer
50                               &dwData))         // size of data buffer
51         {
52             bRet = FALSE;
53             break;
54         }
55
56         *pdwPathBufSize = dwData;
57
58     } while (0);
59
60     if (hKey != NULL)
61         RegCloseKey(hKey);
62
63     return bRet;
64 }
65
66 //
67 // Ensure name for message file is in proper location in Registry.
68 //
69 static BOOL
70 AddEventSource()
71 {
72     HKEY        hKey = NULL, hLogKey;
73     UCHAR       szBuf[MAX_PATH] = "afsd_service.exe";
74     DWORD       dwData, dwDisposition;
75     static BOOL bRet = TRUE;
76     static BOOL bOnce = TRUE;
77
78     if (!bOnce)
79         return bRet;
80
81     if ( RegOpenKeyEx( HKEY_LOCAL_MACHINE, AFSREG_APPLOG_SUBKEY, 0,
82                        KEY_SET_VALUE, &hLogKey ) )
83     {
84         // nope - create it
85         if ( RegCreateKeyEx(HKEY_LOCAL_MACHINE, AFSREG_APPLOG_SUBKEY, 0,
86                              NULL, REG_OPTION_NON_VOLATILE,
87                              KEY_ALL_ACCESS, NULL, &hLogKey,
88                              &dwDisposition))
89         {
90             bRet = FALSE;
91             goto done;
92         }
93     }
94
95     // Let's see if key already exists as a subkey under the
96     // Application key in the EventLog registry key.  If not,
97     // create it.
98     if ( RegOpenKeyEx( hLogKey, AFSREG_CLT_APPLOG_SUBKEY, 0,
99                        KEY_SET_VALUE, &hKey ) )
100     {
101         // nope - create it
102         if ( RegCreateKeyEx(hLogKey, AFSREG_CLT_APPLOG_SUBKEY, 0,
103                              NULL, REG_OPTION_NON_VOLATILE,
104                              KEY_ALL_ACCESS, NULL, &hKey,
105                              &dwDisposition))
106         {
107             bRet = FALSE;
108             goto done;
109         }
110     }
111
112     // Add the name to the EventMessageFile subkey.
113     if ( RegSetValueEx( hKey,                   // subkey handle
114                         AFSREG_APPLOG_MSGFILE_VALUE,    // value name
115                         0,                      // must be zero
116                         REG_SZ,                 // value type
117                         (LPBYTE) szBuf,         // pointer to value data
118                         (DWORD)strlen(szBuf) + 1))      // length of value data
119     {
120         bRet = FALSE;
121         goto done;
122     }
123
124     // Set the supported event types in the TypesSupported subkey.
125     dwData = EVENTLOG_ERROR_TYPE | EVENTLOG_WARNING_TYPE |
126         EVENTLOG_INFORMATION_TYPE;
127
128     if ( RegSetValueEx( hKey,                   // subkey handle
129                         AFSREG_APPLOG_MSGTYPE_VALUE,    // value name
130                         0,                      // must be zero
131                         REG_DWORD,              // value type
132                         (LPBYTE) &dwData,       // pointer to value data
133                         sizeof(DWORD)))         // length of value data
134     {
135         bRet = FALSE;
136         goto done;
137     }
138
139   done:
140     if (hKey != NULL)
141         RegCloseKey(hKey);
142
143     if (hLogKey != NULL)
144         RegCloseKey(hLogKey);
145
146     return bRet;
147 }
148
149 // Log an event with a formatted system message as the (only) substitution
150 // string, from the given message ID.
151 VOID
152 LogEventMessage(WORD wEventType, DWORD dwEventID, DWORD dwMessageID)
153 {
154     LPTSTR msgBuf;
155
156     FormatMessage(FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_ALLOCATE_BUFFER,
157                    NULL, dwMessageID, 0, (LPTSTR)&msgBuf, 0, NULL);
158     LogEvent(wEventType, dwEventID, msgBuf, NULL);
159     LocalFree(msgBuf);
160 }
161
162 //
163 // Use the ReportEvent API to write an entry to the system event log.
164 //
165 #define MAXARGS 8
166 #define STRLEN  128
167
168 VOID
169 LogEvent(WORD wEventType, DWORD dwEventID, ...)
170 {
171     va_list     listArgs;
172     HANDLE      hEventSource;
173     HANDLE      hMutex = NULL;
174     LPTSTR      lpArgs[MAXARGS];
175     CHAR        lpStrings[MAXARGS][STRLEN];
176     static CHAR lpLastStrings[MAXARGS][STRLEN];
177     WORD        wNumArgs = 0;
178     static WORD wLastNumArgs = MAXARGS;
179     static time_t lastMessageTime = 0;
180     static WORD wLastEventType = 0;
181     static DWORD dwLastEventID = 0;
182     time_t      now;
183     DWORD       code;
184     BOOL        bLogMessage = TRUE;
185     WORD        i = 0, j;
186
187     // Ensure that our event source is properly initialized.
188     if (!AddEventSource())
189         return;
190
191     // Get a handle to the event log.
192     hEventSource = RegisterEventSource(NULL, AFS_DAEMON_EVENT_NAME);
193     if (hEventSource == NULL)
194         return;
195
196     // Construct the array of substitution strings.
197     va_start(listArgs, dwEventID);
198
199     switch ( dwEventID ) {
200     case MSG_FLUSH_NO_SHARE_NAME:
201     case MSG_FLUSH_NO_MEMORY:
202     case MSG_FLUSH_IMPERSONATE_ERROR:
203     case MSG_FLUSH_UNEXPECTED_EVENT:
204     case MSG_UNHANDLED_EXCEPTION:
205     case MSG_SMB_ZERO_TRANSACTION_COUNT:
206     case MSG_SERVICE_INCORRECT_VERSIONS:
207     case MSG_SERVICE_STOPPING:
208     case MSG_SERVICE_STOPPED:
209     case MSG_SERVICE_ERROR_STOP:
210     case MSG_CRYPT_OFF:
211     case MSG_CRYPT_ON:
212         break;
213     case MSG_SERVICE_START_PENDING:
214         wNumArgs = 1;
215         lpArgs[0] = AFSVersion;
216         break;
217     case MSG_SERVICE_RUNNING:
218         wNumArgs = 1;
219         if (smb_Enabled && RDR_Initialized)
220             lpArgs[0] = "SMB and RDR interfaces";
221         else if (smb_Enabled)
222             lpArgs[0] = "SMB interface";
223         else if (RDR_Initialized)
224             lpArgs[0] = "RDR interface";
225         else
226             lpArgs[0] = "No active interface";
227         break;
228     case MSG_FLUSH_BAD_SHARE_NAME:
229     case MSG_FLUSH_OPEN_ENUM_ERROR:
230     case MSG_FLUSH_ENUM_ERROR:
231     case MSG_FLUSH_FAILED:
232     case MSG_RX_HARD_DEAD_TIME_EXCEEDED:
233     case MSG_SERVICE_ERROR_STOP_WITH_MSG:
234     case MSG_SMB_SEND_PACKET_FAILURE:
235     case MSG_UNEXPECTED_SMB_SESSION_CLOSE:
236     case MSG_RX_MSGSIZE_EXCEEDED:
237     case MSG_RX_BUSY_CALL_CHANNEL:
238         wNumArgs = 1;
239         lpArgs[0] = va_arg(listArgs, LPTSTR);
240         break;
241     case MSG_TIME_FLUSH_PER_VOLUME:
242     case MSG_TIME_FLUSH_TOTAL:
243     case MSG_SMB_MAX_MPX_COUNT:
244     case MSG_SMB_MAX_BUFFER_SIZE:
245         wNumArgs = 2;
246         lpArgs[0] = va_arg(listArgs, LPTSTR);
247         lpArgs[1] = va_arg(listArgs, LPTSTR);
248         break;
249     case MSG_SERVER_REPORTS_VNOVOL:
250     case MSG_SERVER_REPORTS_VMOVED:
251     case MSG_SERVER_REPORTS_VOFFLINE:
252     case MSG_SERVER_REPORTS_VSALVAGE:
253     case MSG_SERVER_REPORTS_VNOSERVICE:
254     case MSG_SERVER_REPORTS_VIO:
255     case MSG_SERVER_REPORTS_VBUSY:
256     case MSG_SERVER_REPORTS_VRESTARTING:
257         wNumArgs = 3;
258         lpArgs[0] = va_arg(listArgs, LPTSTR);
259         StringCbPrintf(lpStrings[1],STRLEN,"%d",va_arg(listArgs,afs_int32));
260         lpArgs[1] = lpStrings[1];
261         lpArgs[2] = va_arg(listArgs, LPTSTR);
262         break;
263     case MSG_ALL_SERVERS_BUSY:
264     case MSG_ALL_SERVERS_OFFLINE:
265     case MSG_ALL_SERVERS_DOWN:
266     case MSG_RX_IDLE_DEAD_TIMEOUT:
267         wNumArgs = 2;
268         lpArgs[0] = va_arg(listArgs, LPTSTR);
269         StringCbPrintf(lpStrings[1],STRLEN,"%d",va_arg(listArgs,afs_int32));
270         lpArgs[1] = lpStrings[1];
271         break;
272     case MSG_BAD_SMB_PARAM:
273         wNumArgs = 5;
274         lpArgs[0] = va_arg(listArgs, LPTSTR);
275         StringCbPrintf(lpStrings[1],STRLEN,"%d",va_arg(listArgs,int));
276         StringCbPrintf(lpStrings[2],STRLEN,"%d",va_arg(listArgs,int));
277         StringCbPrintf(lpStrings[3],STRLEN,"%d",va_arg(listArgs,int));
278         StringCbPrintf(lpStrings[4],STRLEN,"%d",va_arg(listArgs,WORD));
279         lpArgs[1] = lpStrings[1];
280         lpArgs[2] = lpStrings[2];
281         lpArgs[3] = lpStrings[3];
282         lpArgs[4] = lpStrings[4];
283         break;
284     case MSG_BAD_SMB_PARAM_WITH_OFFSET:
285         wNumArgs = 6;
286         lpArgs[0] = va_arg(listArgs, LPTSTR);
287         StringCbPrintf(lpStrings[1],STRLEN,"%d",va_arg(listArgs,int));
288         StringCbPrintf(lpStrings[2],STRLEN,"%d",va_arg(listArgs,int));
289         StringCbPrintf(lpStrings[3],STRLEN,"%d",va_arg(listArgs,int));
290         StringCbPrintf(lpStrings[4],STRLEN,"%d",va_arg(listArgs,int));
291         StringCbPrintf(lpStrings[5],STRLEN,"%d",va_arg(listArgs,WORD));
292         lpArgs[1] = lpStrings[1];
293         lpArgs[2] = lpStrings[2];
294         lpArgs[3] = lpStrings[3];
295         lpArgs[4] = lpStrings[4];
296         lpArgs[5] = lpStrings[5];
297         break;
298     case MSG_BAD_SMB_TOO_SHORT:
299     case MSG_BAD_SMB_INVALID:
300     case MSG_BAD_SMB_INCOMPLETE:
301         wNumArgs = 1;
302         StringCbPrintf(lpStrings[0],STRLEN,"%d",va_arg(listArgs,WORD));
303         lpArgs[0] = lpStrings[0];
304         break;
305     case MSG_SMB_SESSION_START:
306         wNumArgs = 1;
307         StringCbPrintf(lpStrings[0],STRLEN,"%d",va_arg(listArgs,long));
308         lpArgs[0] = lpStrings[0];
309         break;
310     case MSG_BAD_SMB_WRONG_SESSION:
311         wNumArgs = 2;
312         StringCbPrintf(lpStrings[0],STRLEN,"%d",va_arg(listArgs,DWORD));
313         StringCbPrintf(lpStrings[1],STRLEN,"%d",va_arg(listArgs,WORD));
314         lpArgs[0] = lpStrings[0];
315         lpArgs[1] = lpStrings[1];
316         break;
317     case MSG_BAD_VCP:
318         wNumArgs = 4;
319         StringCbPrintf(lpStrings[0],STRLEN,"%d",va_arg(listArgs,UCHAR));
320         StringCbPrintf(lpStrings[1],STRLEN,"%d",va_arg(listArgs,UCHAR));
321         StringCbPrintf(lpStrings[2],STRLEN,"%d",va_arg(listArgs,UCHAR));
322         StringCbPrintf(lpStrings[3],STRLEN,"%d",va_arg(listArgs,UCHAR));
323         lpArgs[0] = lpStrings[0];
324         lpArgs[1] = lpStrings[1];
325         lpArgs[2] = lpStrings[2];
326         lpArgs[3] = lpStrings[3];
327         break;
328     case MSG_SERVICE_ERROR_STOP_WITH_MSG_AND_LOCATION:
329         wNumArgs = 3;
330         lpArgs[0] = va_arg(listArgs, LPTSTR);
331         StringCbPrintf(lpStrings[1],STRLEN,"%d",va_arg(listArgs,int));
332         lpArgs[1] = lpStrings[1];
333         lpArgs[2] = va_arg(listArgs,LPTSTR);
334         break;
335     case MSG_DIRTY_BUFFER_AT_SHUTDOWN:
336         wNumArgs = 6;
337         lpArgs[0] = va_arg(listArgs, LPTSTR);
338         lpArgs[1] = va_arg(listArgs, LPTSTR);
339         StringCbPrintf(lpStrings[2],STRLEN,"%u",va_arg(listArgs,int));
340         StringCbPrintf(lpStrings[3],STRLEN,"%u",va_arg(listArgs,int));
341         StringCbPrintf(lpStrings[4],STRLEN,"%I64u",va_arg(listArgs,afs_int64));
342         StringCbPrintf(lpStrings[5],STRLEN,"%I64u",va_arg(listArgs,afs_int64));
343         lpArgs[2] = lpStrings[2];
344         lpArgs[3] = lpStrings[3];
345         lpArgs[4] = lpStrings[4];
346         lpArgs[5] = lpStrings[5];
347         break;
348     }
349     va_end(listArgs);
350
351     // Make sure we were not given too many args.
352     if (wNumArgs >= MAXARGS)
353         goto done;
354
355     hMutex = CreateMutex( NULL, TRUE, "AFSD Event Log Mutex");
356     if (hMutex == NULL)
357         goto done;
358
359     if (GetLastError() == ERROR_ALREADY_EXISTS) {
360         code = WaitForSingleObject( hMutex, 500);
361         if (code != WAIT_OBJECT_0)
362             goto done;
363     }
364
365     /*
366      * We rate limit consecutive duplicate messages to one every
367      * five seconds.
368      */
369     now = time(NULL);
370     if (now < lastMessageTime + 5 &&
371         wEventType == wLastEventType &&
372         dwEventID == dwLastEventID &&
373         wNumArgs == wLastNumArgs) {
374         for (i=0; i<wNumArgs; i++) {
375             if ( strncmp(lpArgs[i], lpLastStrings[i], STRLEN))
376                 break;
377         }
378         if (i == wNumArgs)
379             bLogMessage = FALSE;
380     }
381
382     if ( bLogMessage) {
383         wLastNumArgs = wNumArgs;
384         wLastEventType = wEventType;
385         dwLastEventID = dwEventID;
386         lastMessageTime = now;
387
388         for ( j = (i == wNumArgs ? 0 : i) ; i < wNumArgs; i++) {
389             StringCbCopyEx( lpLastStrings[i], STRLEN, lpArgs[i], NULL, NULL, STRSAFE_NULL_ON_FAILURE);
390         }
391     }
392
393     ReleaseMutex(hMutex);
394
395     // Log the event.
396     if ( bLogMessage)
397         code = ReportEvent(hEventSource,                // handle of event source
398                            wEventType,          // event type
399                            0,                   // event category
400                            dwEventID,           // event ID
401                            NULL,                        // current user's SID
402                            wNumArgs,            // strings in lpszArgs
403                            0,                   // no bytes of raw data
404                            wNumArgs ? lpArgs : NULL,// array of error strings
405                            NULL);                       // no raw data
406
407   done:
408     if (hMutex)
409         CloseHandle(hMutex);
410
411     DeregisterEventSource(hEventSource);
412 }
413
414