1/**
2 *
3 * TODO: description
4 *
5 * This file is a part of USB SCSI CAM for Haiku.
6 * May be used under terms of the MIT License
7 *
8 * Author(s):
9 * 	Siarzhuk Zharski <imker@gmx.li>
10 *
11 *
12 */
13/** tracing support implementation */
14
15#include "usb_scsi.h"
16#include "tracing.h"
17
18#include <stdio.h>
19#include <unistd.h> /* posix file i/o - create, write, close */
20#include <malloc.h>
21#include <string.h>
22#include <driver_settings.h>
23
24/** private log path name */
25static const char *private_log_path = "/var/log/"MODULE_NAME".log";
26
27static const char *log_port_name	= MODULE_NAME"-logging";
28
29#ifdef BUILD_LOG_DAEMON
30
31int main(int argc, char**argv)
32{
33	if(B_NAME_NOT_FOUND == find_port(log_port_name)){
34		bool b_screen = (argc > 1);
35		port_id pid = create_port(1000, log_port_name);
36		while(true){
37			int32 code;
38			char buffer[1024 + 1];
39			size_t sz = read_port_etc(pid, &code, buffer, 1024, B_TIMEOUT, 1000 * 1000);
40			if(sz != B_TIMED_OUT){
41				if(b_screen){
42					buffer[sz] = 0;
43					printf(buffer);
44				} else {
45					FILE *f = fopen(private_log_path, "a");
46					fwrite(buffer, sz, 1, f);
47					fclose(f);
48				}
49			}
50		}
51	}
52	return 0;
53}
54
55#else /* BUILD_LOG_DAEMON */
56
57/** is activity logging on or off? */
58#if DEBUG
59bool b_log = true;
60#else
61bool b_log = false;
62#endif
63/** logging in private file */
64bool b_log_file		= false;
65/** appending logs to previous log sessions */
66bool b_log_append	= false;
67/** log SCSI commands */
68bool b_log_scsi_cmd = false;
69/** log USB bulk callback function activity */
70bool b_log_bulk_cb	= false;
71
72bool b_log_protocol = false;
73//bool b_log_CSW = false;
74//bool b_log_CDB = false;
75bool b_log_data_processing = false;
76bool b_log_sense_data	   = false;
77/** log time at wich logging event occured */
78static bool b_log_time	   = false;
79/** log thread id from wich logging performed */
80static bool b_log_thid	   = false;
81/** log thread name from wich logging performed */
82static bool b_log_thname   = false;
83/** semaphore id used to synchronizing logging requests */
84//static sem_id loglock;
85/** log result of READ_CAPACITY command */
86bool b_log_capacity = false;
87
88
89/**
90	\fn: load_log_settings
91	\param sh: driver_settings handle
92	called from main driver settings loading procedure to load log-related
93	parameters
94*/
95void
96load_log_settings(void *sh)
97{
98	if(sh){
99#if !DEBUG
100		b_log			= get_driver_boolean_parameter(sh, "debug_output", b_log, true);
101#endif
102		b_log_file		= get_driver_boolean_parameter(sh, "debug_output_in_file",
103																														 b_log_file, true);
104		b_log_append	= ! get_driver_boolean_parameter(sh, "debug_output_file_rewrite",
105																														!b_log_append, true);
106		b_log_time		= get_driver_boolean_parameter(sh, "debug_trace_time",
107																														 b_log_time, false);
108		b_log_thid		= get_driver_boolean_parameter(sh, "debug_trace_threadid",
109																														 b_log_thid, false);
110		b_log_thname	= get_driver_boolean_parameter(sh, "debug_trace_thread_name",
111																														 b_log_thname, false);
112		b_log_scsi_cmd	= get_driver_boolean_parameter(sh, "debug_trace_commands",
113																														 b_log_scsi_cmd, false);
114		b_log_bulk_cb	= get_driver_boolean_parameter(sh, "debug_trace_bulk_callback",
115																														 b_log_bulk_cb, false);
116		b_log_protocol	= get_driver_boolean_parameter(sh, "debug_trace_protocol",
117																														 b_log_protocol, false);
118		b_log_data_processing =
119						get_driver_boolean_parameter(sh, "debug_trace_data_io",
120										b_log_data_processing, false);
121		b_log_sense_data =
122						get_driver_boolean_parameter(sh, "debug_trace_sense_data",
123										b_log_sense_data, false);
124		b_log_capacity	= get_driver_boolean_parameter(sh, "debug_trace_capacity",
125										b_log_capacity, false);
126		if(!b_log_file){ /* some information is already in system log entries */
127			b_log_thid	 = false;
128			b_log_thname = false;
129		}
130	}
131}
132/**
133	\fn: create_log
134	called to [re]create private log file
135*/
136void
137create_log(void)
138{
139	int flags = O_WRONLY | O_CREAT | ((!b_log_append) ? O_TRUNC : 0);
140	if(b_log_file){
141		close(open(private_log_path, flags, 0666));
142	}
143}
144
145/**
146	\fn: usb_scsi_trace
147	\param b_force: if true - output message ignoring current logging state
148	\param fmt: format string used in message formatting
149	\param ...: variable argument used in message formatting
150	formats and traces messages to current debug output target.
151*/
152void
153usb_scsi_trace(bool b_force, const char *fmt, ...)
154{
155	if(b_force || b_log){
156		va_list arg_list;
157		static char *prefix = MODULE_NAME":";
158		static char buf[1024];
159		char *buf_ptr = buf;
160		port_id pid = find_port(log_port_name);
161		bool b_no_port = (pid == B_NAME_NOT_FOUND);
162		if(!b_log_file || b_no_port){ /* it's not a good idea to add prefix in private file */
163			strcpy(buf, prefix);
164			buf_ptr += strlen(prefix);
165		}
166		if(b_log_time){ /* add time of logging this string */
167			bigtime_t time = system_time();
168			uint32 msec = time / 1000;
169			uint32 sec	= msec / 1000;
170			sprintf(buf_ptr, "%02ld.%02ld.%03ld:", sec / 60, sec % 60, msec % 1000);
171			buf_ptr += strlen(buf_ptr);
172		}
173		if(b_log_thid){ /* add id of the calling thread */
174			thread_id tid = find_thread(0);
175			thread_info tinfo = {0};
176			if(b_log_thname){ /* add name of the calling thread */
177				get_thread_info(tid, &tinfo);
178			}
179			sprintf(buf_ptr, "['%s':%lx]:", tinfo.name, tid);
180			buf_ptr += strlen(buf_ptr);
181		}
182		va_start(arg_list, fmt);
183		vsprintf(buf_ptr, fmt, arg_list);
184		va_end(arg_list);
185		if(b_log_file && !b_no_port){ /* write in private log file */
186			if(B_OK != write_port_etc(pid, 0, buf, strlen(buf), B_TIMEOUT, 0))
187				dprintf("%s", buf);
188		} else /* write in system log*/
189			dprintf("%s", buf);
190	}
191}
192/**
193	\fn: trace_CCB_HEADER
194	\param ccbh: struct to be traced
195	traces CCB_HEADER struct to current debug output target
196*/
197void
198usb_scsi_trace_CCB_HEADER(const CCB_HEADER *ccbh)
199{
200	TRACE("CCB_HEADER:%08x\n"
201		"	phys_addr:%ld\n"
202		"	cam_ccb_len:%d\n"
203		"	cam_func_code:%02x\n"
204		"	cam_status:%02x\n"
205		"	cam_hrsvd0:%02x\n"
206		"	cam_path_id:%02x\n"
207		"	cam_target_id:%02x\n"
208		"	cam_target_lun:%02x\n"
209		"	cam_flags:%08x\n",
210			ccbh,
211			ccbh->phys_addr,
212			ccbh->cam_ccb_len,
213			ccbh->cam_func_code,
214			ccbh->cam_status,
215			ccbh->cam_hrsvd0,
216			ccbh->cam_path_id,
217			ccbh->cam_target_id,
218			ccbh->cam_target_lun,
219			ccbh->cam_flags);
220}
221/**
222	\fn: trace_CCB_SCSIIO
223	\param ccbio: struct to be traced
224	traces CCB_SCSIIO struct to current debug output target
225*/
226void
227usb_scsi_trace_CCB_SCSIIO(const CCB_SCSIIO *ccbio)
228{
229	TRACE("CCB_SCSIIO:%08x\n", ccbio);
230	usb_scsi_trace_CCB_HEADER(&ccbio->cam_ch);
231	TRACE("	cam_pdrv_ptr:%08x\n"
232		"	cam_next_ccb:%08x\n"
233		"	cam_req_map:%08x\n"
234		"	(*cam_cbfcnp):%08x\n"
235		"	cam_data_ptr:%08x\n"
236		"	cam_dxfer_len:%ld\n"
237		"	cam_sense_ptr:%08x\n"
238		"	cam_sense_len:%d\n"
239		"	cam_cdb_len:%d\n"
240		"	cam_sglist_cnt:%d\n"
241		"	cam_sort:%d\n"
242		"	cam_scsi_status:%02x\n"
243		"	cam_sense_resid:%d\n"
244		"	cam_resid:%d\n"
245		"	cam_timeout:%d\n"
246		"	cam_msg_ptr:%08x\n"
247		"	cam_msgb_len:%d\n"
248		"	cam_vu_flags:%04x\n"
249		"	cam_tag_action:%d\n",
250	ccbio->cam_pdrv_ptr,
251	ccbio->cam_next_ccb,
252	ccbio->cam_req_map,
253	ccbio->cam_cbfcnp,
254	ccbio->cam_data_ptr,
255	ccbio->cam_dxfer_len,
256	ccbio->cam_sense_ptr,
257	ccbio->cam_sense_len,
258	ccbio->cam_cdb_len,
259	ccbio->cam_sglist_cnt,
260	ccbio->cam_sort,
261	ccbio->cam_scsi_status,
262	ccbio->cam_sense_resid,
263	ccbio->cam_resid,
264	ccbio->cam_timeout,
265	ccbio->cam_msg_ptr,
266	ccbio->cam_msgb_len,
267	ccbio->cam_vu_flags,
268	ccbio->cam_tag_action);
269
270	usb_scsi_trace_bytes("CDB_UN:\n", ccbio->cam_cdb_io.cam_cdb_bytes, IOCDBLEN);
271}
272/**
273	\fn: usb_scsi_command_trace
274	\param b_hlight: highlight command and prefix it with spec. charachter
275	\param cmd: array of bytes to be traced. typically pointer SCSI command buffer
276	\param cmdlen: size of buffer in cmd parameter
277	traces SCSI commands into debug output target.can highlight and prefix the
278	text with special charachter and color for two different types
279	of commands.
280*/
281void
282usb_scsi_trace_command(bool b_hlight, const uint8 *cmd, size_t cmdlen)
283{
284	size_t len = min(cmdlen, 12); /* command length watchdog */
285	char hl_mask[] = "\33[%sCMD:\33[0m";
286	char prefix[sizeof(hl_mask) + 6];
287	if(b_log_file){ /* compose CMD prefix */
288		sprintf(prefix, "%sCMD:", b_hlight ? "=>":"");
289	} else {
290		sprintf(prefix, hl_mask, b_hlight ? "33m=>":"32m");
291	}
292	usb_scsi_trace_bytes(prefix, cmd, len); /* append command bytes to log */
293}
294/**
295	\fn:usb_scsi_bytes_trace
296	\param bytes:array of bytes to be traced.
297	\param bytes_len: size of buffer in bytes parameter
298	traces buffer bytes one by one into debug output target.
299*/
300void
301usb_scsi_trace_bytes(const char *prefix, const uint8 *bytes, size_t bytes_len)
302{
303	size_t len = min(bytes_len, 0x100); /* length watchdog */
304	char truncTail[] = "<TRUNC>\n";
305	char *pbuf = (char *)malloc(len * 3 + sizeof(truncTail) + strlen(prefix) + 1);
306	if(pbuf){
307		size_t i = 0;
308		char *p = pbuf;
309		strcpy(p, prefix);
310		p += strlen(prefix);
311		for(;i < len; i++){
312			sprintf(p, " %02x", bytes[i]);
313			p += strlen(p);
314		}
315		/* user should be informed about truncation too*/
316		strcpy(p, (len < bytes_len) ? truncTail : "\n");
317		TRACE(pbuf);
318		free(pbuf);
319	} else {
320		TRACE_ALWAYS("usb_scsi_trace_bytes:error allocate "
321																			"memory for tracing %d bytes\n", len);
322	}
323}
324
325void usb_scsi_trace_sgb(const char *prefix, sg_buffer *sgb)
326{
327	char sgbHead[] = "SGB:";
328	size_t i = 0;
329	size_t len = strlen(prefix) + strlen(sgbHead) + sgb->count * 9;
330	char *sgbPrefix = (char*)malloc(len);
331	if(0 != sgbPrefix){
332		sg_buffer sgb_own;
333		size_t sgb_len = 0;
334		char *p = sgbPrefix;
335		strcpy(p, prefix);
336		p += strlen(p);
337		strcpy(p, sgbHead);
338		p += strlen(p);
339		i = 0;
340		for(; i < sgb->count; i++){
341			sprintf(p, "%lX,", sgb->piov[i].iov_len);
342			sgb_len += sgb->piov[i].iov_len;
343			p += strlen(p);
344		}
345		if(B_OK == realloc_sg_buffer(&sgb_own, sgb_len)){
346			sg_memcpy(&sgb_own, 0, sgb, 0, sgb_len);
347			/* assume non-fragmented memory	*/
348			usb_scsi_trace_bytes(sgbPrefix, sgb_own.piov->iov_base, sgb_own.piov->iov_len);
349			free_sg_buffer(&sgb_own);
350		} else {
351			TRACE_ALWAYS("usb_scsi_trace_sgb:error allocate sgb for %d bytes\n", sgb_len);
352		}
353	} else {
354		TRACE_ALWAYS("usb_scsi_trace_sgb:error allocate memory for %d bytes\n", len);
355	}
356}
357
358void usb_scsi_trace_SG(iovec *sg, int count)
359{
360	char sg_mask[] = "SG:{%s}\n";
361	char truncTail[] = "<TRUNC>";
362	size_t trunc_count = min(count, 0x20); /* length watchdog */
363	size_t len = sizeof(sg_mask) + sizeof(truncTail) + trunc_count * 16;
364	char *pbuf = (char *)malloc(len + 1);
365	if(pbuf){
366		int i = 0;
367		char *p = pbuf;
368		for(; i < trunc_count; i++){
369			sprintf(p, (!i) ? "%d" : ", %d", sg[i].iov_len);
370			p += strlen(p);
371		}
372		/* user should be informed about truncation too*/
373		if(trunc_count < count)
374			strcpy(p, truncTail);
375
376		TRACE(sg_mask, pbuf);
377		free(pbuf);
378	} else {
379		TRACE_ALWAYS("usb_scsi_trace_SG:error allocate "
380																		"memory for tracing %d SG entries\n", trunc_count);
381	}
382}
383
384#endif /* BUILD_LOG_DAEMON */
385
386