1/*
2 * Copyright 2004-2005, Axel D��rfler, axeld@pinc-software.de. All rights reserved.
3 * Distributed under the terms of the MIT License.
4 */
5
6
7#include <KernelExport.h>
8
9#include <util/kernel_cpp.h>
10#include <thread.h>
11#include <file_cache.h>
12#include <fs/fd.h>
13#include <generic_syscall.h>
14
15#include <unistd.h>
16#include <stdlib.h>
17#include <string.h>
18#include <stdio.h>
19#include <errno.h>
20
21
22//#define TRACE_CACHE_MODULE
23#ifdef TRACE_CACHE_MODULE
24#	define TRACE(x) dprintf x
25#else
26#	define TRACE(x) ;
27#endif
28
29
30// generic syscall interface
31#define CACHE_LOG_SYSCALLS "cache_log"
32#define CACHE_LOG_SET_MODULE	1
33
34
35struct cache_log {
36	team_id		team;
37	char		team_name[B_OS_NAME_LENGTH];
38	mount_id	device;
39	vnode_id	parent;
40	vnode_id	node;
41	union {
42		char	file_name[B_FILE_NAME_LENGTH];
43		struct {
44			char	**args;
45			int32	arg_count;
46			team_id	parent;
47		}		launch;
48		int32	access_type;
49	};
50	bigtime_t	timestamp;
51	uint8		type;
52	uint8		action;
53};
54
55static const bigtime_t kLogTimeout = 50000;	// 50 ms
56static const int32 kLogWriterFrequency = 1;	// every tenth second
57static const uint32 kNumLogEntries = 6000;
58static const uint32 kLogWriteThreshold = 2000;
59
60static struct cache_log sLogEntries[kNumLogEntries];
61static uint32 sCurrentEntry;
62static sem_id sLogEntrySem;
63static struct mutex sLock;
64static int sLogFile;
65static struct cache_module_info *sCacheModule;
66
67
68static void
69put_log_entry(cache_log *log)
70{
71	mutex_unlock(&sLock);
72}
73
74
75static cache_log *
76get_log_entry()
77{
78	if (acquire_sem_etc(sLogEntrySem, 1, B_RELATIVE_TIMEOUT, kLogTimeout) != B_OK) {
79		dprintf("log: Dropped log entry!\n");
80		return NULL;
81	}
82
83	mutex_lock(&sLock);
84	cache_log *log = &sLogEntries[sCurrentEntry++];
85
86	Thread *thread = thread_get_current_thread();
87	log->team = thread->team->id;
88	strlcpy(log->team_name, thread->name, B_OS_NAME_LENGTH);
89
90	log->timestamp = system_time();
91
92	return log;
93}
94
95
96static void
97log_node_opened(void *vnode, int32 fdType, mount_id device, vnode_id parent,
98	vnode_id node, const char *name, off_t size)
99{
100	cache_log *log = get_log_entry();
101	if (log == NULL)
102		return;
103
104	if (name != NULL)
105		strlcpy(log->file_name, name, B_FILE_NAME_LENGTH);
106	else {
107		log->file_name[0] = '\0';
108		vfs_get_vnode_name(vnode, log->file_name, B_FILE_NAME_LENGTH);
109	}
110	log->action = 'o';
111	log->type = fdType;
112
113	log->device = device;
114	log->parent = parent;
115	log->node = node;
116	log->timestamp = system_time();
117
118	TRACE(("log: added entry %s, <%c%d> %ld:%lld:%lld:%s\n", log->team_name, log->action,
119		log->type, device, parent, node, log->file_name));
120
121	put_log_entry(log);
122
123	if (sCacheModule != NULL && sCacheModule->node_opened != NULL)
124		sCacheModule->node_opened(vnode, fdType, device, parent, node, name, size);
125}
126
127
128static void
129log_node_closed(void *vnode, int32 fdType, mount_id device, vnode_id node, int32 accessType)
130{
131	cache_log *log = get_log_entry();
132	if (log == NULL)
133		return;
134
135	log->action = 'c';
136	log->type = fdType;
137
138	log->device = device;
139	log->parent = -1;
140	log->node = node;
141
142	log->access_type = accessType;
143
144	TRACE(("log: added entry %s, <c%d> %ld:%lld, %ld\n",
145		log->team_name, log->type, device, node, accessType));
146
147	put_log_entry(log);
148
149	if (sCacheModule != NULL && sCacheModule->node_closed != NULL)
150		sCacheModule->node_closed(vnode, fdType, device, node, accessType);
151}
152
153
154static void
155log_node_launched(size_t argCount, char * const *args)
156{
157	cache_log *log = get_log_entry();
158	if (log == NULL)
159		return;
160
161	log->action = 'l';
162	log->type = FDTYPE_FILE;
163
164	log->launch.args = (char **)malloc(argCount * sizeof(char *));
165	log->launch.arg_count = argCount;
166
167	for (uint32 i = 0; i < argCount; i++) {
168		if  (i == 0) {
169			// cut off path from parent team name
170			Team *team = thread_get_current_thread()->team;
171			char name[B_OS_NAME_LENGTH];
172			cpu_status state;
173
174			state = disable_interrupts();
175			GRAB_TEAM_LOCK();
176
177			log->launch.parent = team->parent->id;
178			strlcpy(name, team->parent->main_thread->name, B_OS_NAME_LENGTH);
179
180			RELEASE_TEAM_LOCK();
181			restore_interrupts(state);
182
183			log->launch.args[0] = strdup(name);
184		} else
185			log->launch.args[i] = strdup(args[i]);
186
187		// remove newlines from the arguments
188		char *newline;
189		while ((newline = strchr(log->launch.args[i], '\n')) != NULL) {
190			*newline = ' ';
191		}
192	}
193
194	if (vfs_get_cwd(&log->device, &log->parent) != B_OK) {
195		log->device = -1;
196		log->parent = -1;
197	}
198
199	TRACE(("log: added entry %s, <l> %ld:%lld %s ...\n", log->team_name,
200		log->device, log->parent, args[0]));
201
202	put_log_entry(log);
203
204	if (sCacheModule != NULL && sCacheModule->node_launched != NULL)
205		sCacheModule->node_launched(argCount, args);
206}
207
208
209static status_t
210log_control(const char *subsystem, uint32 function,
211	void *buffer, size_t bufferSize)
212{
213	switch (function) {
214		case CACHE_LOG_SET_MODULE:
215		{
216			cache_module_info *module = sCacheModule;
217
218			// unset previous module
219
220			if (sCacheModule != NULL) {
221				sCacheModule = NULL;
222				snooze(100000);	// 0.1 secs
223				put_module(module->info.name);
224			}
225
226			// get new module, if any
227
228			if (buffer == NULL)
229				return B_OK;
230
231			char name[B_FILE_NAME_LENGTH];
232			if (!IS_USER_ADDRESS(buffer)
233				|| user_strlcpy(name, (char *)buffer, B_FILE_NAME_LENGTH) < B_OK)
234				return B_BAD_ADDRESS;
235
236			if (strncmp(name, CACHE_MODULES_NAME, strlen(CACHE_MODULES_NAME)))
237				return B_BAD_VALUE;
238
239			TRACE(("log_control: set module %s!\n", name));
240
241			status_t status = get_module(name, (module_info **)&module);
242			if (status == B_OK)
243				sCacheModule = module;
244
245			return status;
246		}
247	}
248
249	return B_BAD_HANDLER;
250}
251
252
253static void
254log_writer_daemon(void *arg, int /*iteration*/)
255{
256	mutex_lock(&sLock);
257
258	if (sCurrentEntry > kLogWriteThreshold || arg != NULL) {
259		off_t fileSize = 0;
260		struct stat stat;
261		if (fstat(sLogFile, &stat) == 0) {
262			// enlarge file, so that it can be written faster
263			fileSize = stat.st_size;
264			ftruncate(sLogFile, fileSize + 512 * 1024);
265		} else
266			stat.st_size = -1;
267
268		for (uint32 i = 0; i < sCurrentEntry; i++) {
269			cache_log *log = &sLogEntries[i];
270			char line[1236];
271			ssize_t length = 0;
272
273			switch (log->action) {
274				case 'l':	// launch
275					length = snprintf(line, sizeof(line), "%ld: %lld \"%s\" l %ld:%lld %ld \"%s\" ",
276								log->team, log->timestamp, log->team_name,
277								log->device, log->parent, log->launch.parent,
278								log->launch.args[0]);
279					length = std::min(length, (ssize_t)sizeof(line) - 1);
280
281					for (int32 j = 1; j < log->launch.arg_count; j++) {
282						// write argument list one by one, so that we can deal
283						// with very long argument lists
284						ssize_t written = write(sLogFile, line, length);
285						if (written != length) {
286							dprintf("log: must drop log entries: %ld, %s!\n",
287								written, strerror(written));
288							break;
289						} else
290							fileSize += length;
291
292						strlcpy(line, log->launch.args[j], sizeof(line));
293						length = strlcat(line, "\xb0 ", sizeof(line));
294					}
295
296					if (length >= (ssize_t)sizeof(line))
297						length = sizeof(line) - 1;
298
299					line[length - 1] = '\n';
300					break;
301
302				case 'c':	// close
303					length = snprintf(line, sizeof(line), "%ld: %lld \"%s\" c%d %ld:%lld %ld\n",
304						log->team, log->timestamp, log->team_name, log->type,
305						log->device, log->node, log->access_type);
306					length = std::min(length, (ssize_t)sizeof(line) - 1);
307					break;
308
309				default:	// open, ?
310					length = snprintf(line, sizeof(line), "%ld: %lld \"%s\" %c%d %ld:%lld:%lld:\"%s\"\n",
311						log->team, log->timestamp, log->team_name, log->action, log->type, log->device,
312						log->parent, log->node, log->file_name);
313					length = std::min(length, (ssize_t)sizeof(line) - 1);
314					break;
315			}
316
317			ssize_t written = write(sLogFile, line, length);
318			if (written != length) {
319				dprintf("log: must drop log entries: %ld, %s!\n", written, strerror(written));
320				break;
321			} else
322				fileSize += length;
323		}
324
325		// shrink file again to its real size
326		if (stat.st_size != -1)
327			ftruncate(sLogFile, fileSize);
328
329		// need to free any launch log items (also if writing fails)
330
331		for (uint32 i = 0; i < sCurrentEntry; i++) {
332			cache_log *log = &sLogEntries[i];
333			if (log->action != 'l')
334				continue;
335
336			for (int32 j = 0; j < log->launch.arg_count; j++)
337				free(log->launch.args[j]);
338
339			free(log->launch.args);
340		}
341
342		release_sem_etc(sLogEntrySem, sCurrentEntry, B_DO_NOT_RESCHEDULE);
343		sCurrentEntry = 0;
344	}
345
346	mutex_unlock(&sLock);
347}
348
349
350static void
351uninit_log(void)
352{
353	TRACE(("** log uninit - \n"));
354
355	unregister_kernel_daemon(log_writer_daemon, NULL);
356	unregister_generic_syscall(CACHE_LOG_SYSCALLS, 1);
357
358	log_writer_daemon((void *)true, 0);
359		// flush log entries
360
361	delete_sem(sLogEntrySem);
362	mutex_destroy(&sLock);
363	close(sLogFile);
364
365	if (sCacheModule != NULL)
366		put_module(sCacheModule->info.name);
367
368	TRACE(("** - log uninit\n"));
369}
370
371
372static status_t
373init_log(void)
374{
375	TRACE(("** log init\n"));
376
377	int32 number = 0;
378	do {
379		char name[B_FILE_NAME_LENGTH];
380		snprintf(name, sizeof(name), "/var/log/cache_%03ld", number++);
381
382		sLogFile = open(name, O_WRONLY | O_CREAT | O_EXCL, DEFFILEMODE);
383	} while (sLogFile < 0 && errno == B_FILE_EXISTS);
384
385	if (sLogFile < B_OK) {
386		dprintf("log: opening log file failed: %s\n", strerror(errno));
387		return sLogFile;
388	}
389
390	sLogEntrySem = create_sem(kNumLogEntries, "cache log entries");
391	if (sLogEntrySem >= B_OK) {
392		mutex_init(&sLock, "log cache module");
393		register_kernel_daemon(log_writer_daemon, NULL, kLogWriterFrequency);
394		register_generic_syscall(CACHE_LOG_SYSCALLS, log_control, 1, 0);
395
396		TRACE(("** - log init\n"));
397		return B_OK;
398	}
399
400	close(sLogFile);
401	return B_ERROR;
402}
403
404
405static status_t
406log_std_ops(int32 op, ...)
407{
408	switch (op) {
409		case B_MODULE_INIT:
410			return init_log();
411
412		case B_MODULE_UNINIT:
413			uninit_log();
414			return B_OK;
415
416		default:
417			return B_ERROR;
418	}
419}
420
421
422static struct cache_module_info sLogCacheModule = {
423	{
424		CACHE_MODULES_NAME "/log/v1",
425		0,
426		log_std_ops,
427	},
428	log_node_opened,
429	log_node_closed,
430	log_node_launched,
431};
432
433
434module_info *modules[] = {
435	(module_info *)&sLogCacheModule,
436	NULL
437};
438