265482713Simker *
365482713Simker * TODO: description
406437987SMatt Madia *
506437987SMatt Madia * This file is a part of USB SCSI CAM for Haiku.
665482713Simker * May be used under terms of the MIT License
765482713Simker *
865482713Simker * Author(s):
965482713Simker * 	Siarzhuk Zharski <imker@gmx.li>
1006437987SMatt Madia *
1106437987SMatt Madia *
12b3d94504SStephan Aßmus */
13b3d94504SStephan Aßmus/** tracing support implementation */
14b3d94504SStephan Aßmus
15b3d94504SStephan Aßmus#include "usb_scsi.h"
16b3d94504SStephan Aßmus#include "tracing.h"
17b3d94504SStephan Aßmus
18b3d94504SStephan Aßmus#include <stdio.h>
19b3d94504SStephan Aßmus#include <unistd.h> /* posix file i/o - create, write, close */
20b3d94504SStephan Aßmus#include <malloc.h>
2106437987SMatt Madia#include <string.h>
2206437987SMatt Madia#include <driver_settings.h>
23b3d94504SStephan Aßmus
24b3d94504SStephan Aßmus/** private log path name */
25b3d94504SStephan Aßmusstatic const char *private_log_path = "/var/log/"MODULE_NAME".log";
26b3d94504SStephan Aßmus
2765482713Simkerstatic const char *log_port_name	= MODULE_NAME"-logging";
2906437987SMatt Madia#ifdef BUILD_LOG_DAEMON
30b3d94504SStephan Aßmus
31b3d94504SStephan Aßmusint main(int argc, char**argv)
32b3d94504SStephan Aßmus{
3365482713Simker	if(B_NAME_NOT_FOUND == find_port(log_port_name)){
3465482713Simker		bool b_screen = (argc > 1);
3565482713Simker		port_id pid = create_port(1000, log_port_name);
3665482713Simker		while(true){
3765482713Simker			int32 code;
3865482713Simker			char buffer[1024 + 1];
3965482713Simker			size_t sz = read_port_etc(pid, &code, buffer, 1024, B_TIMEOUT, 1000 * 1000);
4065482713Simker			if(sz != B_TIMED_OUT){
4165482713Simker				if(b_screen){
4265482713Simker					buffer[sz] = 0;
4365482713Simker					printf(buffer);
4465482713Simker				} else {
4565482713Simker					FILE *f = fopen(private_log_path, "a");
4665482713Simker					fwrite(buffer, sz, 1, f);
4765482713Simker					fclose(f);
4806437987SMatt Madia				}
4965482713Simker			}
5065482713Simker		}
5106437987SMatt Madia	}
5265482713Simker	return 0;
53b3d94504SStephan Aßmus}
54b3d94504SStephan Aßmus
55b3d94504SStephan Aßmus#else /* BUILD_LOG_DAEMON */
56b3d94504SStephan Aßmus
57b3d94504SStephan Aßmus/** is activity logging on or off? */
58b3d94504SStephan Aßmus#if DEBUG
5906437987SMatt Madiabool b_log = true;
60b3d94504SStephan Aßmus#else
61b3d94504SStephan Aßmusbool b_log = false;
62b3d94504SStephan Aßmus#endif
63b3d94504SStephan Aßmus/** logging in private file */
6465482713Simkerbool b_log_file		= false;
65b3d94504SStephan Aßmus/** appending logs to previous log sessions */
6665482713Simkerbool b_log_append	= false;
67b3d94504SStephan Aßmus/** log SCSI commands */
68b3d94504SStephan Aßmusbool b_log_scsi_cmd = false;
69b3d94504SStephan Aßmus/** log USB bulk callback function activity */
7065482713Simkerbool b_log_bulk_cb	= false;
71b3d94504SStephan Aßmus
72b3d94504SStephan Aßmusbool b_log_protocol = false;
73b3d94504SStephan Aßmus//bool b_log_CSW = false;
74b3d94504SStephan Aßmus//bool b_log_CDB = false;
75b3d94504SStephan Aßmusbool b_log_data_processing = false;
7665482713Simkerbool b_log_sense_data	   = false;
77b3d94504SStephan Aßmus/** log time at wich logging event occured */
7865482713Simkerstatic bool b_log_time	   = false;
79b3d94504SStephan Aßmus/** log thread id from wich logging performed */
8065482713Simkerstatic bool b_log_thid	   = false;
81b3d94504SStephan Aßmus/** log thread name from wich logging performed */
8206437987SMatt Madiastatic bool b_log_thname   = false;
83b3d94504SStephan Aßmus/** semaphore id used to synchronizing logging requests */
84b3d94504SStephan Aßmus//static sem_id loglock;
85b3d94504SStephan Aßmus/** log result of READ_CAPACITY command */
86b3d94504SStephan Aßmusbool b_log_capacity = false;
87b3d94504SStephan Aßmus
89b3d94504SStephan Aßmus/**
9065482713Simker	\fn: load_log_settings
9165482713Simker	\param sh: driver_settings handle
9265482713Simker	called from main driver settings loading procedure to load log-related
9365482713Simker	parameters
94b3d94504SStephan Aßmus*/
95b3d94504SStephan Aßmusvoid
96b3d94504SStephan Aßmusload_log_settings(void *sh)
97b3d94504SStephan Aßmus{
9865482713Simker	if(sh){
99b3d94504SStephan Aßmus#if !DEBUG
10065482713Simker		b_log			= get_driver_boolean_parameter(sh, "debug_output", b_log, true);
101b3d94504SStephan Aßmus#endif
10265482713Simker		b_log_file		= get_driver_boolean_parameter(sh, "debug_output_in_file",
10365482713Simker																														 b_log_file, true);
10465482713Simker		b_log_append	= ! get_driver_boolean_parameter(sh, "debug_output_file_rewrite",
10565482713Simker																														!b_log_append, true);
10665482713Simker		b_log_time		= get_driver_boolean_parameter(sh, "debug_trace_time",
10765482713Simker																														 b_log_time, false);
10865482713Simker		b_log_thid		= get_driver_boolean_parameter(sh, "debug_trace_threadid",
10965482713Simker																														 b_log_thid, false);
11065482713Simker		b_log_thname	= get_driver_boolean_parameter(sh, "debug_trace_thread_name",
11165482713Simker																														 b_log_thname, false);
11265482713Simker		b_log_scsi_cmd	= get_driver_boolean_parameter(sh, "debug_trace_commands",
11365482713Simker																														 b_log_scsi_cmd, false);
11465482713Simker		b_log_bulk_cb	= get_driver_boolean_parameter(sh, "debug_trace_bulk_callback",
11565482713Simker																														 b_log_bulk_cb, false);
11665482713Simker		b_log_protocol	= get_driver_boolean_parameter(sh, "debug_trace_protocol",
11765482713Simker																														 b_log_protocol, false);
11865482713Simker		b_log_data_processing =
11965482713Simker						get_driver_boolean_parameter(sh, "debug_trace_data_io",
12065482713Simker										b_log_data_processing, false);
12106437987SMatt Madia		b_log_sense_data =
12265482713Simker						get_driver_boolean_parameter(sh, "debug_trace_sense_data",
12365482713Simker										b_log_sense_data, false);
12465482713Simker		b_log_capacity	= get_driver_boolean_parameter(sh, "debug_trace_capacity",
12506437987SMatt Madia										b_log_capacity, false);
12665482713Simker		if(!b_log_file){ /* some information is already in system log entries */
12765482713Simker			b_log_thid	 = false;
12865482713Simker			b_log_thname = false;
12965482713Simker		}
13065482713Simker	}
131b3d94504SStephan Aßmus}
132b3d94504SStephan Aßmus/**
13365482713Simker	\fn: create_log
13465482713Simker	called to [re]create private log file
135b3d94504SStephan Aßmus*/
136b3d94504SStephan Aßmusvoid
138b3d94504SStephan Aßmus{
13965482713Simker	int flags = O_WRONLY | O_CREAT | ((!b_log_append) ? O_TRUNC : 0);
14065482713Simker	if(b_log_file){
14165482713Simker		close(open(private_log_path, flags, 0666));
14265482713Simker	}
143b3d94504SStephan Aßmus}
144b3d94504SStephan Aßmus
145b3d94504SStephan Aßmus/**
14665482713Simker	\fn: usb_scsi_trace
14706437987SMatt Madia	\param b_force: if true - output message ignoring current logging state
14865482713Simker	\param fmt: format string used in message formatting
14965482713Simker	\param ...: variable argument used in message formatting
15065482713Simker	formats and traces messages to current debug output target.
151b3d94504SStephan Aßmus*/
152b3d94504SStephan Aßmusvoid
153b3d94504SStephan Aßmususb_scsi_trace(bool b_force, const char *fmt, ...)
154b3d94504SStephan Aßmus{
15565482713Simker	if(b_force || b_log){
15665482713Simker		va_list arg_list;
157354543faSimker		static char *prefix = MODULE_NAME":";
15865482713Simker		static char buf[1024];
15965482713Simker		char *buf_ptr = buf;
16065482713Simker		port_id pid = find_port(log_port_name);
16165482713Simker		bool b_no_port = (pid == B_NAME_NOT_FOUND);
16265482713Simker		if(!b_log_file || b_no_port){ /* it's not a good idea to add prefix in private file */
16365482713Simker			strcpy(buf, prefix);
16465482713Simker			buf_ptr += strlen(prefix);
16565482713Simker		}
16665482713Simker		if(b_log_time){ /* add time of logging this string */
16765482713Simker			bigtime_t time = system_time();
16865482713Simker			uint32 msec = time / 1000;
16965482713Simker			uint32 sec	= msec / 1000;
17065482713Simker			sprintf(buf_ptr, "%02ld.%02ld.%03ld:", sec / 60, sec % 60, msec % 1000);
17165482713Simker			buf_ptr += strlen(buf_ptr);
17265482713Simker		}
17365482713Simker		if(b_log_thid){ /* add id of the calling thread */
17465482713Simker			thread_id tid = find_thread(0);
17565482713Simker			thread_info tinfo = {0};
17665482713Simker			if(b_log_thname){ /* add name of the calling thread */
17765482713Simker				get_thread_info(tid, &tinfo);
17865482713Simker			}
17965482713Simker			sprintf(buf_ptr, "['%s':%lx]:", tinfo.name, tid);
18065482713Simker			buf_ptr += strlen(buf_ptr);
18165482713Simker		}
18265482713Simker		va_start(arg_list, fmt);
18365482713Simker		vsprintf(buf_ptr, fmt, arg_list);
18465482713Simker		va_end(arg_list);
18565482713Simker		if(b_log_file && !b_no_port){ /* write in private log file */
18665482713Simker			if(B_OK != write_port_etc(pid, 0, buf, strlen(buf), B_TIMEOUT, 0))
18765482713Simker				dprintf(buf);
18865482713Simker		} else /* write in system log*/
18965482713Simker			dprintf(buf);
19065482713Simker	}
191b3d94504SStephan Aßmus}
192b3d94504SStephan Aßmus/**
19365482713Simker	\fn: trace_CCB_HEADER
19465482713Simker	\param ccbh: struct to be traced
19565482713Simker	traces CCB_HEADER struct to current debug output target
196b3d94504SStephan Aßmus*/
197b3d94504SStephan Aßmusvoid
198b3d94504SStephan Aßmususb_scsi_trace_CCB_HEADER(const CCB_HEADER *ccbh)
199b3d94504SStephan Aßmus{
20065482713Simker	TRACE("CCB_HEADER:%08x\n"
20165482713Simker		"	phys_addr:%ld\n"
20265482713Simker		"	cam_ccb_len:%d\n"
20365482713Simker		"	cam_func_code:%02x\n"
20465482713Simker		"	cam_status:%02x\n"
20565482713Simker		"	cam_hrsvd0:%02x\n"
20665482713Simker		"	cam_path_id:%02x\n"
20765482713Simker		"	cam_target_id:%02x\n"
20865482713Simker		"	cam_target_lun:%02x\n"
20965482713Simker		"	cam_flags:%08x\n",
21065482713Simker			ccbh,
21165482713Simker			ccbh->phys_addr,
212b3d94504SStephan Aßmus			ccbh->cam_ccb_len,
213b3d94504SStephan Aßmus			ccbh->cam_func_code,
214b3d94504SStephan Aßmus			ccbh->cam_status,
215b3d94504SStephan Aßmus			ccbh->cam_hrsvd0,
216b3d94504SStephan Aßmus			ccbh->cam_path_id,
217b3d94504SStephan Aßmus			ccbh->cam_target_id,
218b3d94504SStephan Aßmus			ccbh->cam_target_lun,
219b3d94504SStephan Aßmus			ccbh->cam_flags);
220b3d94504SStephan Aßmus}
221b3d94504SStephan Aßmus/**
22265482713Simker	\fn: trace_CCB_SCSIIO
22365482713Simker	\param ccbio: struct to be traced
22465482713Simker	traces CCB_SCSIIO struct to current debug output target
225b3d94504SStephan Aßmus*/
226b3d94504SStephan Aßmusvoid
227b3d94504SStephan Aßmususb_scsi_trace_CCB_SCSIIO(const CCB_SCSIIO *ccbio)
228b3d94504SStephan Aßmus{
22965482713Simker	TRACE("CCB_SCSIIO:%08x\n", ccbio);
23065482713Simker	usb_scsi_trace_CCB_HEADER(&ccbio->cam_ch);
23165482713Simker	TRACE("	cam_pdrv_ptr:%08x\n"
23265482713Simker		"	cam_next_ccb:%08x\n"
23365482713Simker		"	cam_req_map:%08x\n"
23465482713Simker		"	(*cam_cbfcnp):%08x\n"
23565482713Simker		"	cam_data_ptr:%08x\n"
23665482713Simker		"	cam_dxfer_len:%ld\n"
23765482713Simker		"	cam_sense_ptr:%08x\n"
23865482713Simker		"	cam_sense_len:%d\n"
23965482713Simker		"	cam_cdb_len:%d\n"
24065482713Simker		"	cam_sglist_cnt:%d\n"
24165482713Simker		"	cam_sort:%d\n"
24265482713Simker		"	cam_scsi_status:%02x\n"
24365482713Simker		"	cam_sense_resid:%d\n"
24465482713Simker		"	cam_resid:%d\n"
24565482713Simker		"	cam_timeout:%d\n"
24665482713Simker		"	cam_msg_ptr:%08x\n"
24765482713Simker		"	cam_msgb_len:%d\n"
24865482713Simker		"	cam_vu_flags:%04x\n"
24965482713Simker		"	cam_tag_action:%d\n",
250b3d94504SStephan Aßmus	ccbio->cam_pdrv_ptr,
251b3d94504SStephan Aßmus	ccbio->cam_next_ccb,
252b3d94504SStephan Aßmus	ccbio->cam_req_map,
253b3d94504SStephan Aßmus	ccbio->cam_cbfcnp,
254b3d94504SStephan Aßmus	ccbio->cam_data_ptr,
255b3d94504SStephan Aßmus	ccbio->cam_dxfer_len,
256b3d94504SStephan Aßmus	ccbio->cam_sense_ptr,
257b3d94504SStephan Aßmus	ccbio->cam_sense_len,
258b3d94504SStephan Aßmus	ccbio->cam_cdb_len,
259b3d94504SStephan Aßmus	ccbio->cam_sglist_cnt,
260b3d94504SStephan Aßmus	ccbio->cam_sort,
261b3d94504SStephan Aßmus	ccbio->cam_scsi_status,
262b3d94504SStephan Aßmus	ccbio->cam_sense_resid,
263b3d94504SStephan Aßmus	ccbio->cam_resid,
264b3d94504SStephan Aßmus	ccbio->cam_timeout,
265b3d94504SStephan Aßmus	ccbio->cam_msg_ptr,
266b3d94504SStephan Aßmus	ccbio->cam_msgb_len,
267b3d94504SStephan Aßmus	ccbio->cam_vu_flags,
268b3d94504SStephan Aßmus	ccbio->cam_tag_action);
269b3d94504SStephan Aßmus
27006437987SMatt Madia	usb_scsi_trace_bytes("CDB_UN:\n", ccbio->cam_cdb_io.cam_cdb_bytes, IOCDBLEN);
271b3d94504SStephan Aßmus}
272b3d94504SStephan Aßmus/**
27365482713Simker	\fn: usb_scsi_command_trace
27465482713Simker	\param b_hlight: highlight command and prefix it with spec. charachter
27565482713Simker	\param cmd: array of bytes to be traced. typically pointer SCSI command buffer
27606437987SMatt Madia	\param cmdlen: size of buffer in cmd parameter
27765482713Simker	traces SCSI commands into debug output target.can highlight and prefix the
27865482713Simker	text with special charachter and color for two different types
27965482713Simker	of commands.
280b3d94504SStephan Aßmus*/
281b3d94504SStephan Aßmusvoid
282b3d94504SStephan Aßmususb_scsi_trace_command(bool b_hlight, const uint8 *cmd, size_t cmdlen)
283b3d94504SStephan Aßmus{
28465482713Simker	size_t len = min(cmdlen, 12); /* command length watchdog */
28565482713Simker	char hl_mask[] = "\33[%sCMD:\33[0m";
28665482713Simker	char prefix[sizeof(hl_mask) + 6];
28765482713Simker	if(b_log_file){ /* compose CMD prefix */
28865482713Simker		sprintf(prefix, "%sCMD:", b_hlight ? "=>":"");
28965482713Simker	} else {
29065482713Simker		sprintf(prefix, hl_mask, b_hlight ? "33m=>":"32m");
29165482713Simker	}
29265482713Simker	usb_scsi_trace_bytes(prefix, cmd, len); /* append command bytes to log */
293b3d94504SStephan Aßmus}
294b3d94504SStephan Aßmus/**
29565482713Simker	\fn:usb_scsi_bytes_trace
29665482713Simker	\param bytes:array of bytes to be traced.
29706437987SMatt Madia	\param bytes_len: size of buffer in bytes parameter
29865482713Simker	traces buffer bytes one by one into debug output target.
299b3d94504SStephan Aßmus*/
300b3d94504SStephan Aßmusvoid
301b3d94504SStephan Aßmususb_scsi_trace_bytes(const char *prefix, const uint8 *bytes, size_t bytes_len)
302b3d94504SStephan Aßmus{
30365482713Simker	size_t len = min(bytes_len, 0x100); /* length watchdog */
30465482713Simker	char truncTail[] = "<TRUNC>\n";
30565482713Simker	char *pbuf = (char *)malloc(len * 3 + sizeof(truncTail) + strlen(prefix) + 1);
30665482713Simker	if(pbuf){
30765482713Simker		size_t i = 0;
30865482713Simker		char *p = pbuf;
30965482713Simker		strcpy(p, prefix);
31065482713Simker		p += strlen(prefix);
31165482713Simker		for(;i < len; i++){
31265482713Simker			sprintf(p, " %02x", bytes[i]);
31365482713Simker			p += strlen(p);
31465482713Simker		}
31565482713Simker		/* user should be informed about truncation too*/
31665482713Simker		strcpy(p, (len < bytes_len) ? truncTail : "\n");
31765482713Simker		TRACE(pbuf);
31865482713Simker		free(pbuf);
31965482713Simker	} else {
32065482713Simker		TRACE_ALWAYS("usb_scsi_trace_bytes:error allocate "
32165482713Simker																			"memory for tracing %d bytes\n", len);
32206437987SMatt Madia	}
323b3d94504SStephan Aßmus}
324b3d94504SStephan Aßmus
325b3d94504SStephan Aßmusvoid usb_scsi_trace_sgb(const char *prefix, sg_buffer *sgb)
326b3d94504SStephan Aßmus{
32765482713Simker	char sgbHead[] = "SGB:";
32865482713Simker	size_t i = 0;
32965482713Simker	size_t len = strlen(prefix) + strlen(sgbHead) + sgb->count * 9;
33065482713Simker	char *sgbPrefix = (char*)malloc(len);
33165482713Simker	if(0 != sgbPrefix){
33265482713Simker		sg_buffer sgb_own;
33365482713Simker		size_t sgb_len = 0;
33465482713Simker		char *p = sgbPrefix;
33565482713Simker		strcpy(p, prefix);
33665482713Simker		p += strlen(p);
33765482713Simker		strcpy(p, sgbHead);
33865482713Simker		p += strlen(p);
33965482713Simker		i = 0;
34065482713Simker		for(; i < sgb->count; i++){
34165482713Simker			sprintf(p, "%lX,", sgb->piov[i].iov_len);
34265482713Simker			sgb_len += sgb->piov[i].iov_len;
34365482713Simker			p += strlen(p);
34465482713Simker		}
34565482713Simker		if(B_OK == realloc_sg_buffer(&sgb_own, sgb_len)){
34665482713Simker			sg_memcpy(&sgb_own, 0, sgb, 0, sgb_len);
34765482713Simker			/* assume non-fragmented memory	*/
34865482713Simker			usb_scsi_trace_bytes(sgbPrefix, sgb_own.piov->iov_base, sgb_own.piov->iov_len);
34965482713Simker			free_sg_buffer(&sgb_own);
35065482713Simker		} else {
35165482713Simker			TRACE_ALWAYS("usb_scsi_trace_sgb:error allocate sgb for %d bytes\n", sgb_len);
35265482713Simker		}
35365482713Simker	} else {
35465482713Simker		TRACE_ALWAYS("usb_scsi_trace_sgb:error allocate memory for %d bytes\n", len);
35565482713Simker	}
356b3d94504SStephan Aßmus}
357b3d94504SStephan Aßmus
358b3d94504SStephan Aßmusvoid usb_scsi_trace_SG(iovec *sg, int count)
359b3d94504SStephan Aßmus{
36065482713Simker	char sg_mask[] = "SG:{%s}\n";
36165482713Simker	char truncTail[] = "<TRUNC>";
36265482713Simker	size_t trunc_count = min(count, 0x20); /* length watchdog */
36306437987SMatt Madia	size_t len = sizeof(sg_mask) + sizeof(truncTail) + trunc_count * 16;
36406437987SMatt Madia	char *pbuf = (char *)malloc(len + 1);
36565482713Simker	if(pbuf){
36665482713Simker		int i = 0;
36765482713Simker		char *p = pbuf;
36865482713Simker		for(; i < trunc_count; i++){
36965482713Simker			sprintf(p, (!i) ? "%d" : ", %d", sg[i].iov_len);
37065482713Simker			p += strlen(p);
37165482713Simker		}
37265482713Simker		/* user should be informed about truncation too*/
37365482713Simker		if(trunc_count < count)
37465482713Simker			strcpy(p, truncTail);
37506437987SMatt Madia
37665482713Simker		TRACE(sg_mask, pbuf);
37765482713Simker		free(pbuf);
37865482713Simker	} else {
37965482713Simker		TRACE_ALWAYS("usb_scsi_trace_SG:error allocate "
38065482713Simker																		"memory for tracing %d SG entries\n", trunc_count);
38106437987SMatt Madia	}
382b3d94504SStephan Aßmus}
383b3d94504SStephan Aßmus
384b3d94504SStephan Aßmus#endif /* BUILD_LOG_DAEMON */