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 */ 25 static const char *private_log_path = "/var/log/"MODULE_NAME".log"; 26 27 static const char *log_port_name = MODULE_NAME"-logging"; 28 29 #ifdef BUILD_LOG_DAEMON 30 31 int 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 59 bool b_log = true; 60 #else 61 bool b_log = false; 62 #endif 63 /** logging in private file */ 64 bool b_log_file = false; 65 /** appending logs to previous log sessions */ 66 bool b_log_append = false; 67 /** log SCSI commands */ 68 bool b_log_scsi_cmd = false; 69 /** log USB bulk callback function activity */ 70 bool b_log_bulk_cb = false; 71 72 bool b_log_protocol = false; 73 //bool b_log_CSW = false; 74 //bool b_log_CDB = false; 75 bool b_log_data_processing = false; 76 bool b_log_sense_data = false; 77 /** log time at wich logging event occured */ 78 static bool b_log_time = false; 79 /** log thread id from wich logging performed */ 80 static bool b_log_thid = false; 81 /** log thread name from wich logging performed */ 82 static 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 */ 86 bool 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 */ 95 void 96 load_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 */ 136 void 137 create_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 */ 152 void 153 usb_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 */ 197 void 198 usb_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 */ 226 void 227 usb_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 */ 281 void 282 usb_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 */ 300 void 301 usb_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 325 void 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 358 void 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