haiku.git

/**
 *
 * TODO: description
 *
 * This file is a part of USB SCSI CAM for Haiku.
 * May be used under terms of the MIT License
 *
 * Author(s):
 * 	Siarzhuk Zharski <imker@gmx.li>
 *
 *
 */
/** tracing support implementation */

#include "usb_scsi.h"
#include "tracing.h"

#include <stdio.h>
#include <unistd.h> /* posix file i/o - create, write, close */
#include <malloc.h>
#include <string.h>
#include <driver_settings.h>

/** private log path name */
static const char *private_log_path = "/var/log/"MODULE_NAME".log";

static const char *log_port_name	= MODULE_NAME"-logging";

#ifdef BUILD_LOG_DAEMON

int main(int argc, char**argv)
{
	if(B_NAME_NOT_FOUND == find_port(log_port_name)){
		bool b_screen = (argc > 1);
		port_id pid = create_port(1000, log_port_name);
		while(true){
			int32 code;
			char buffer[1024 + 1];
			size_t sz = read_port_etc(pid, &code, buffer, 1024, B_TIMEOUT, 1000 * 1000);
			if(sz != B_TIMED_OUT){
				if(b_screen){
					buffer[sz] = 0;
					printf(buffer);
				} else {
					FILE *f = fopen(private_log_path, "a");
					fwrite(buffer, sz, 1, f);
					fclose(f);
				}
			}
		}
	}
	return 0;
}

#else /* BUILD_LOG_DAEMON */

/** is activity logging on or off? */
#if DEBUG
bool b_log = true;
#else
bool b_log = false;
#endif
/** logging in private file */
bool b_log_file		= false;
/** appending logs to previous log sessions */
bool b_log_append	= false;
/** log SCSI commands */
bool b_log_scsi_cmd = false;
/** log USB bulk callback function activity */
bool b_log_bulk_cb	= false;

bool b_log_protocol = false;
//bool b_log_CSW = false;
//bool b_log_CDB = false;
bool b_log_data_processing = false;
bool b_log_sense_data	   = false;
/** log time at wich logging event occured */
static bool b_log_time	   = false;
/** log thread id from wich logging performed */
static bool b_log_thid	   = false;
/** log thread name from wich logging performed */
static bool b_log_thname   = false;
/** semaphore id used to synchronizing logging requests */
//static sem_id loglock;
/** log result of READ_CAPACITY command */
bool b_log_capacity = false;


/**
	\fn: load_log_settings
	\param sh: driver_settings handle
	called from main driver settings loading procedure to load log-related
	parameters
*/
void
load_log_settings(void *sh)
{
	if(sh){
#if !DEBUG
		b_log			= get_driver_boolean_parameter(sh, "debug_output", b_log, true);
#endif
		b_log_file		= get_driver_boolean_parameter(sh, "debug_output_in_file",
																														 b_log_file, true);
		b_log_append	= ! get_driver_boolean_parameter(sh, "debug_output_file_rewrite",
																														!b_log_append, true);
		b_log_time		= get_driver_boolean_parameter(sh, "debug_trace_time",
																														 b_log_time, false);
		b_log_thid		= get_driver_boolean_parameter(sh, "debug_trace_threadid",
																														 b_log_thid, false);
		b_log_thname	= get_driver_boolean_parameter(sh, "debug_trace_thread_name",
																														 b_log_thname, false);
		b_log_scsi_cmd	= get_driver_boolean_parameter(sh, "debug_trace_commands",
																														 b_log_scsi_cmd, false);
		b_log_bulk_cb	= get_driver_boolean_parameter(sh, "debug_trace_bulk_callback",
																														 b_log_bulk_cb, false);
		b_log_protocol	= get_driver_boolean_parameter(sh, "debug_trace_protocol",
																														 b_log_protocol, false);
		b_log_data_processing =
						get_driver_boolean_parameter(sh, "debug_trace_data_io",
										b_log_data_processing, false);
		b_log_sense_data =
						get_driver_boolean_parameter(sh, "debug_trace_sense_data",
										b_log_sense_data, false);
		b_log_capacity	= get_driver_boolean_parameter(sh, "debug_trace_capacity",
										b_log_capacity, false);
		if(!b_log_file){ /* some information is already in system log entries */
			b_log_thid	 = false;
			b_log_thname = false;
		}
	}
}
/**
	\fn: create_log
	called to [re]create private log file
*/
void
create_log(void)
{
	int flags = O_WRONLY | O_CREAT | ((!b_log_append) ? O_TRUNC : 0);
	if(b_log_file){
		close(open(private_log_path, flags, 0666));
	}
}

/**
	\fn: usb_scsi_trace
	\param b_force: if true - output message ignoring current logging state
	\param fmt: format string used in message formatting
	\param ...: variable argument used in message formatting
	formats and traces messages to current debug output target.
*/
void
usb_scsi_trace(bool b_force, const char *fmt, ...)
{
	if(b_force || b_log){
		va_list arg_list;
		static char *prefix = MODULE_NAME":";
		static char buf[1024];
		char *buf_ptr = buf;
		port_id pid = find_port(log_port_name);
		bool b_no_port = (pid == B_NAME_NOT_FOUND);
		if(!b_log_file || b_no_port){ /* it's not a good idea to add prefix in private file */
			strcpy(buf, prefix);
			buf_ptr += strlen(prefix);
		}
		if(b_log_time){ /* add time of logging this string */
			bigtime_t time = system_time();
			uint32 msec = time / 1000;
			uint32 sec	= msec / 1000;
			sprintf(buf_ptr, "%02ld.%02ld.%03ld:", sec / 60, sec % 60, msec % 1000);
			buf_ptr += strlen(buf_ptr);
		}
		if(b_log_thid){ /* add id of the calling thread */
			thread_id tid = find_thread(0);
			thread_info tinfo = {0};
			if(b_log_thname){ /* add name of the calling thread */
				get_thread_info(tid, &tinfo);
			}
			sprintf(buf_ptr, "['%s':%lx]:", tinfo.name, tid);
			buf_ptr += strlen(buf_ptr);
		}
		va_start(arg_list, fmt);
		vsprintf(buf_ptr, fmt, arg_list);
		va_end(arg_list);
		if(b_log_file && !b_no_port){ /* write in private log file */
			if(B_OK != write_port_etc(pid, 0, buf, strlen(buf), B_TIMEOUT, 0))
				dprintf("%s", buf);
		} else /* write in system log*/
			dprintf("%s", buf);
	}
}
/**
	\fn: trace_CCB_HEADER
	\param ccbh: struct to be traced
	traces CCB_HEADER struct to current debug output target
*/
void
usb_scsi_trace_CCB_HEADER(const CCB_HEADER *ccbh)
{
	TRACE("CCB_HEADER:%08x\n"
		"	phys_addr:%ld\n"
		"	cam_ccb_len:%d\n"
		"	cam_func_code:%02x\n"
		"	cam_status:%02x\n"
		"	cam_hrsvd0:%02x\n"
		"	cam_path_id:%02x\n"
		"	cam_target_id:%02x\n"
		"	cam_target_lun:%02x\n"
		"	cam_flags:%08x\n",
			ccbh,
			ccbh->phys_addr,
			ccbh->cam_ccb_len,
			ccbh->cam_func_code,
			ccbh->cam_status,
			ccbh->cam_hrsvd0,
			ccbh->cam_path_id,
			ccbh->cam_target_id,
			ccbh->cam_target_lun,
			ccbh->cam_flags);
}
/**
	\fn: trace_CCB_SCSIIO
	\param ccbio: struct to be traced
	traces CCB_SCSIIO struct to current debug output target
*/
void
usb_scsi_trace_CCB_SCSIIO(const CCB_SCSIIO *ccbio)
{
	TRACE("CCB_SCSIIO:%08x\n", ccbio);
	usb_scsi_trace_CCB_HEADER(&ccbio->cam_ch);
	TRACE("	cam_pdrv_ptr:%08x\n"
		"	cam_next_ccb:%08x\n"
		"	cam_req_map:%08x\n"
		"	(*cam_cbfcnp):%08x\n"
		"	cam_data_ptr:%08x\n"
		"	cam_dxfer_len:%ld\n"
		"	cam_sense_ptr:%08x\n"
		"	cam_sense_len:%d\n"
		"	cam_cdb_len:%d\n"
		"	cam_sglist_cnt:%d\n"
		"	cam_sort:%d\n"
		"	cam_scsi_status:%02x\n"
		"	cam_sense_resid:%d\n"
		"	cam_resid:%d\n"
		"	cam_timeout:%d\n"
		"	cam_msg_ptr:%08x\n"
		"	cam_msgb_len:%d\n"
		"	cam_vu_flags:%04x\n"
		"	cam_tag_action:%d\n",
	ccbio->cam_pdrv_ptr,
	ccbio->cam_next_ccb,
	ccbio->cam_req_map,
	ccbio->cam_cbfcnp,
	ccbio->cam_data_ptr,
	ccbio->cam_dxfer_len,
	ccbio->cam_sense_ptr,
	ccbio->cam_sense_len,
	ccbio->cam_cdb_len,
	ccbio->cam_sglist_cnt,
	ccbio->cam_sort,
	ccbio->cam_scsi_status,
	ccbio->cam_sense_resid,
	ccbio->cam_resid,
	ccbio->cam_timeout,
	ccbio->cam_msg_ptr,
	ccbio->cam_msgb_len,
	ccbio->cam_vu_flags,
	ccbio->cam_tag_action);

	usb_scsi_trace_bytes("CDB_UN:\n", ccbio->cam_cdb_io.cam_cdb_bytes, IOCDBLEN);
}
/**
	\fn: usb_scsi_command_trace
	\param b_hlight: highlight command and prefix it with spec. charachter
	\param cmd: array of bytes to be traced. typically pointer SCSI command buffer
	\param cmdlen: size of buffer in cmd parameter
	traces SCSI commands into debug output target.can highlight and prefix the
	text with special charachter and color for two different types
	of commands.
*/
void
usb_scsi_trace_command(bool b_hlight, const uint8 *cmd, size_t cmdlen)
{
	size_t len = min(cmdlen, 12); /* command length watchdog */
	char hl_mask[] = "\33[%sCMD:\33[0m";
	char prefix[sizeof(hl_mask) + 6];
	if(b_log_file){ /* compose CMD prefix */
		sprintf(prefix, "%sCMD:", b_hlight ? "=>":"");
	} else {
		sprintf(prefix, hl_mask, b_hlight ? "33m=>":"32m");
	}
	usb_scsi_trace_bytes(prefix, cmd, len); /* append command bytes to log */
}
/**
	\fn:usb_scsi_bytes_trace
	\param bytes:array of bytes to be traced.
	\param bytes_len: size of buffer in bytes parameter
	traces buffer bytes one by one into debug output target.
*/
void
usb_scsi_trace_bytes(const char *prefix, const uint8 *bytes, size_t bytes_len)
{
	size_t len = min(bytes_len, 0x100); /* length watchdog */
	char truncTail[] = "<TRUNC>\n";
	char *pbuf = (char *)malloc(len * 3 + sizeof(truncTail) + strlen(prefix) + 1);
	if(pbuf){
		size_t i = 0;
		char *p = pbuf;
		strcpy(p, prefix);
		p += strlen(prefix);
		for(;i < len; i++){
			sprintf(p, " %02x", bytes[i]);
			p += strlen(p);
		}
		/* user should be informed about truncation too*/
		strcpy(p, (len < bytes_len) ? truncTail : "\n");
		TRACE(pbuf);
		free(pbuf);
	} else {
		TRACE_ALWAYS("usb_scsi_trace_bytes:error allocate "
																			"memory for tracing %d bytes\n", len);
	}
}

void usb_scsi_trace_sgb(const char *prefix, sg_buffer *sgb)
{
	char sgbHead[] = "SGB:";
	size_t i = 0;
	size_t len = strlen(prefix) + strlen(sgbHead) + sgb->count * 9;
	char *sgbPrefix = (char*)malloc(len);
	if(0 != sgbPrefix){
		sg_buffer sgb_own;
		size_t sgb_len = 0;
		char *p = sgbPrefix;
		strcpy(p, prefix);
		p += strlen(p);
		strcpy(p, sgbHead);
		p += strlen(p);
		i = 0;
		for(; i < sgb->count; i++){
			sprintf(p, "%lX,", sgb->piov[i].iov_len);
			sgb_len += sgb->piov[i].iov_len;
			p += strlen(p);
		}
		if(B_OK == realloc_sg_buffer(&sgb_own, sgb_len)){
			sg_memcpy(&sgb_own, 0, sgb, 0, sgb_len);
			/* assume non-fragmented memory	*/
			usb_scsi_trace_bytes(sgbPrefix, sgb_own.piov->iov_base, sgb_own.piov->iov_len);
			free_sg_buffer(&sgb_own);
		} else {
			TRACE_ALWAYS("usb_scsi_trace_sgb:error allocate sgb for %d bytes\n", sgb_len);
		}
	} else {
		TRACE_ALWAYS("usb_scsi_trace_sgb:error allocate memory for %d bytes\n", len);
	}
}

void usb_scsi_trace_SG(iovec *sg, int count)
{
	char sg_mask[] = "SG:{%s}\n";
	char truncTail[] = "<TRUNC>";
	size_t trunc_count = min(count, 0x20); /* length watchdog */
	size_t len = sizeof(sg_mask) + sizeof(truncTail) + trunc_count * 16;
	char *pbuf = (char *)malloc(len + 1);
	if(pbuf){
		int i = 0;
		char *p = pbuf;
		for(; i < trunc_count; i++){
			sprintf(p, (!i) ? "%d" : ", %d", sg[i].iov_len);
			p += strlen(p);
		}
		/* user should be informed about truncation too*/
		if(trunc_count < count)
			strcpy(p, truncTail);

		TRACE(sg_mask, pbuf);
		free(pbuf);
	} else {
		TRACE_ALWAYS("usb_scsi_trace_SG:error allocate "
																		"memory for tracing %d SG entries\n", trunc_count);
	}
}

#endif /* BUILD_LOG_DAEMON */