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