haiku.git

/*
 * Copyright 2004-2005, Axel Dörfler, axeld@pinc-software.de. All rights reserved.
 * Distributed under the terms of the MIT License.
 */


#include <KernelExport.h>

#include <util/kernel_cpp.h>
#include <thread.h>
#include <file_cache.h>
#include <fs/fd.h>
#include <generic_syscall.h>

#include <unistd.h>
#include <stdlib.h>
#include <string.h>
#include <stdio.h>
#include <errno.h>


//#define TRACE_CACHE_MODULE
#ifdef TRACE_CACHE_MODULE
#	define TRACE(x) dprintf x
#else
#	define TRACE(x) ;
#endif


// generic syscall interface
#define CACHE_LOG_SYSCALLS "cache_log"
#define CACHE_LOG_SET_MODULE	1


struct cache_log {
	team_id		team;
	char		team_name[B_OS_NAME_LENGTH];
	mount_id	device;
	vnode_id	parent;
	vnode_id	node;
	union {
		char	file_name[B_FILE_NAME_LENGTH];
		struct {
			char	**args;
			int32	arg_count;
			team_id	parent;
		}		launch;
		int32	access_type;
	};
	bigtime_t	timestamp;
	uint8		type;
	uint8		action;
};

static const bigtime_t kLogTimeout = 50000;	// 50 ms
static const int32 kLogWriterFrequency = 1;	// every tenth second
static const uint32 kNumLogEntries = 6000;
static const uint32 kLogWriteThreshold = 2000;

static struct cache_log sLogEntries[kNumLogEntries];
static uint32 sCurrentEntry;
static sem_id sLogEntrySem;
static struct mutex sLock;
static int sLogFile;
static struct cache_module_info *sCacheModule;


static void
put_log_entry(cache_log *log)
{
	mutex_unlock(&sLock);
}


static cache_log *
get_log_entry()
{
	if (acquire_sem_etc(sLogEntrySem, 1, B_RELATIVE_TIMEOUT, kLogTimeout) != B_OK) {
		dprintf("log: Dropped log entry!\n");
		return NULL;
	}

	mutex_lock(&sLock);
	cache_log *log = &sLogEntries[sCurrentEntry++];

	Thread *thread = thread_get_current_thread();
	log->team = thread->team->id;
	strlcpy(log->team_name, thread->name, B_OS_NAME_LENGTH);

	log->timestamp = system_time();

	return log;
}


static void
log_node_opened(void *vnode, int32 fdType, mount_id device, vnode_id parent,
	vnode_id node, const char *name, off_t size)
{
	cache_log *log = get_log_entry();
	if (log == NULL)
		return;

	if (name != NULL)
		strlcpy(log->file_name, name, B_FILE_NAME_LENGTH);
	else {
		log->file_name[0] = '\0';
		vfs_get_vnode_name(vnode, log->file_name, B_FILE_NAME_LENGTH);
	}
	log->action = 'o';
	log->type = fdType;

	log->device = device;
	log->parent = parent;
	log->node = node;
	log->timestamp = system_time();

	TRACE(("log: added entry %s, <%c%d> %ld:%lld:%lld:%s\n", log->team_name, log->action,
		log->type, device, parent, node, log->file_name));

	put_log_entry(log);

	if (sCacheModule != NULL && sCacheModule->node_opened != NULL)
		sCacheModule->node_opened(vnode, fdType, device, parent, node, name, size);
}


static void
log_node_closed(void *vnode, int32 fdType, mount_id device, vnode_id node, int32 accessType)
{
	cache_log *log = get_log_entry();
	if (log == NULL)
		return;

	log->action = 'c';
	log->type = fdType;

	log->device = device;
	log->parent = -1;
	log->node = node;

	log->access_type = accessType;

	TRACE(("log: added entry %s, <c%d> %ld:%lld, %ld\n",
		log->team_name, log->type, device, node, accessType));

	put_log_entry(log);

	if (sCacheModule != NULL && sCacheModule->node_closed != NULL)
		sCacheModule->node_closed(vnode, fdType, device, node, accessType);
}


static void
log_node_launched(size_t argCount, char * const *args)
{
	cache_log *log = get_log_entry();
	if (log == NULL)
		return;

	log->action = 'l';
	log->type = FDTYPE_FILE;

	log->launch.args = (char **)malloc(argCount * sizeof(char *));
	log->launch.arg_count = argCount;

	for (uint32 i = 0; i < argCount; i++) {
		if  (i == 0) {
			// cut off path from parent team name
			Team *team = thread_get_current_thread()->team;
			char name[B_OS_NAME_LENGTH];
			cpu_status state;

			state = disable_interrupts();
			GRAB_TEAM_LOCK();

			log->launch.parent = team->parent->id;
			strlcpy(name, team->parent->main_thread->name, B_OS_NAME_LENGTH);

			RELEASE_TEAM_LOCK();
			restore_interrupts(state);

			log->launch.args[0] = strdup(name);
		} else
			log->launch.args[i] = strdup(args[i]);

		// remove newlines from the arguments
		char *newline;
		while ((newline = strchr(log->launch.args[i], '\n')) != NULL) {
			*newline = ' ';
		}
	}

	if (vfs_get_cwd(&log->device, &log->parent) != B_OK) {
		log->device = -1;
		log->parent = -1;
	}

	TRACE(("log: added entry %s, <l> %ld:%lld %s ...\n", log->team_name,
		log->device, log->parent, args[0]));

	put_log_entry(log);

	if (sCacheModule != NULL && sCacheModule->node_launched != NULL)
		sCacheModule->node_launched(argCount, args);
}


static status_t
log_control(const char *subsystem, uint32 function,
	void *buffer, size_t bufferSize)
{
	switch (function) {
		case CACHE_LOG_SET_MODULE:
		{
			cache_module_info *module = sCacheModule;

			// unset previous module

			if (sCacheModule != NULL) {
				sCacheModule = NULL;
				snooze(100000);	// 0.1 secs
				put_module(module->info.name);
			}

			// get new module, if any

			if (buffer == NULL)
				return B_OK;

			char name[B_FILE_NAME_LENGTH];
			if (!IS_USER_ADDRESS(buffer)
				|| user_strlcpy(name, (char *)buffer, B_FILE_NAME_LENGTH) < B_OK)
				return B_BAD_ADDRESS;

			if (strncmp(name, CACHE_MODULES_NAME, strlen(CACHE_MODULES_NAME)))
				return B_BAD_VALUE;

			TRACE(("log_control: set module %s!\n", name));

			status_t status = get_module(name, (module_info **)&module);
			if (status == B_OK)
				sCacheModule = module;

			return status;
		}
	}

	return B_BAD_HANDLER;
}


static void
log_writer_daemon(void *arg, int /*iteration*/)
{
	mutex_lock(&sLock);

	if (sCurrentEntry > kLogWriteThreshold || arg != NULL) {
		off_t fileSize = 0;
		struct stat stat;
		if (fstat(sLogFile, &stat) == 0) {
			// enlarge file, so that it can be written faster
			fileSize = stat.st_size;
			ftruncate(sLogFile, fileSize + 512 * 1024);
		} else
			stat.st_size = -1;

		for (uint32 i = 0; i < sCurrentEntry; i++) {
			cache_log *log = &sLogEntries[i];
			char line[1236];
			ssize_t length = 0;

			switch (log->action) {
				case 'l':	// launch
					length = snprintf(line, sizeof(line), "%ld: %lld \"%s\" l %ld:%lld %ld \"%s\" ",
								log->team, log->timestamp, log->team_name,
								log->device, log->parent, log->launch.parent,
								log->launch.args[0]);
					length = std::min(length, (ssize_t)sizeof(line) - 1);

					for (int32 j = 1; j < log->launch.arg_count; j++) {
						// write argument list one by one, so that we can deal
						// with very long argument lists
						ssize_t written = write(sLogFile, line, length);
						if (written != length) {
							dprintf("log: must drop log entries: %ld, %s!\n",
								written, strerror(written));
							break;
						} else
							fileSize += length;

						strlcpy(line, log->launch.args[j], sizeof(line));
						length = strlcat(line, "\xb0 ", sizeof(line));
					}

					if (length >= (ssize_t)sizeof(line))
						length = sizeof(line) - 1;

					line[length - 1] = '\n';
					break;

				case 'c':	// close
					length = snprintf(line, sizeof(line), "%ld: %lld \"%s\" c%d %ld:%lld %ld\n",
						log->team, log->timestamp, log->team_name, log->type,
						log->device, log->node, log->access_type);
					length = std::min(length, (ssize_t)sizeof(line) - 1);
					break;

				default:	// open, ?
					length = snprintf(line, sizeof(line), "%ld: %lld \"%s\" %c%d %ld:%lld:%lld:\"%s\"\n",
						log->team, log->timestamp, log->team_name, log->action, log->type, log->device,
						log->parent, log->node, log->file_name);
					length = std::min(length, (ssize_t)sizeof(line) - 1);
					break;
			}

			ssize_t written = write(sLogFile, line, length);
			if (written != length) {
				dprintf("log: must drop log entries: %ld, %s!\n", written, strerror(written));
				break;
			} else
				fileSize += length;
		}

		// shrink file again to its real size
		if (stat.st_size != -1)
			ftruncate(sLogFile, fileSize);

		// need to free any launch log items (also if writing fails)

		for (uint32 i = 0; i < sCurrentEntry; i++) {
			cache_log *log = &sLogEntries[i];
			if (log->action != 'l')
				continue;

			for (int32 j = 0; j < log->launch.arg_count; j++)
				free(log->launch.args[j]);

			free(log->launch.args);
		}

		release_sem_etc(sLogEntrySem, sCurrentEntry, B_DO_NOT_RESCHEDULE);
		sCurrentEntry = 0;
	}

	mutex_unlock(&sLock);
}


static void
uninit_log(void)
{
	TRACE(("** log uninit - \n"));

	unregister_kernel_daemon(log_writer_daemon, NULL);
	unregister_generic_syscall(CACHE_LOG_SYSCALLS, 1);

	log_writer_daemon((void *)true, 0);
		// flush log entries

	delete_sem(sLogEntrySem);
	mutex_destroy(&sLock);
	close(sLogFile);

	if (sCacheModule != NULL)
		put_module(sCacheModule->info.name);

	TRACE(("** - log uninit\n"));
}


static status_t
init_log(void)
{
	TRACE(("** log init\n"));

	int32 number = 0;
	do {
		char name[B_FILE_NAME_LENGTH];
		snprintf(name, sizeof(name), "/var/log/cache_%03ld", number++);

		sLogFile = open(name, O_WRONLY | O_CREAT | O_EXCL, DEFFILEMODE);
	} while (sLogFile < 0 && errno == B_FILE_EXISTS);

	if (sLogFile < B_OK) {
		dprintf("log: opening log file failed: %s\n", strerror(errno));
		return sLogFile;
	}

	sLogEntrySem = create_sem(kNumLogEntries, "cache log entries");
	if (sLogEntrySem >= B_OK) {
		mutex_init(&sLock, "log cache module");
		register_kernel_daemon(log_writer_daemon, NULL, kLogWriterFrequency);
		register_generic_syscall(CACHE_LOG_SYSCALLS, log_control, 1, 0);

		TRACE(("** - log init\n"));
		return B_OK;
	}

	close(sLogFile);
	return B_ERROR;
}


static status_t
log_std_ops(int32 op, ...)
{
	switch (op) {
		case B_MODULE_INIT:
			return init_log();

		case B_MODULE_UNINIT:
			uninit_log();
			return B_OK;

		default:
			return B_ERROR;
	}
}


static struct cache_module_info sLogCacheModule = {
	{
		CACHE_MODULES_NAME "/log/v1",
		0,
		log_std_ops,
	},
	log_node_opened,
	log_node_closed,
	log_node_launched,
};


module_info *modules[] = {
	(module_info *)&sLogCacheModule,
	NULL
};