Allrighty, this patch wraps up my -current work and should establish a nice baseline for my debugging of problems.

Introduce struct sbp_dev.bustgtlun to replace the overloaded show_sdev_info() in most places. This is an optimization of the debug case fortunately. Stash the BB:TT:LL string here for later device_printf() goodness.

More debugging cleanup printf()-->device_printf()

Explicity set the callout sdev->login_callout to acquire the sbp mtx.

Rename sbp_alloc_target() variable i to new_target_id. Clarity is good, even in temporary variables.

Cleanup and document the sbp_login() function. This function is a bit hairy, so document what it's supposed to do.

Add some locking in sbp_probe_target()

Assert the sbp mtx in sbp_write_cmd_locked()

Avoid LoR in sbp_mgm_orb() and assert sbp mtx locked.

Acquire sbp mtx before sbp_mgm_orb() is invoked.

Sean

Index: sbp.c =================================================================== --- sbp.c (revision 188508) +++ sbp.c (working copy) @@ -31,7 +31,7 @@ * ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE * POSSIBILITY OF SUCH DAMAGE. * - * $FreeBSD$ + * $FreeBSD: head/sys/dev/firewire/sbp.c 187993 2009-02-01 23:28:52Z sbruno $ * */

@@ -218,6 +218,7 @@ char vendor[32]; char product[32]; char revision[10]; + char bustgtlun[32]; };

struct sbp_target { @@ -331,7 +332,7 @@ sbp_identify(driver_t *driver, device_t parent) { SBP_DEBUG(0) - printf("sbp_identify\n"); + printf("%s\n", __func__); END_DEBUG

BUS_ADD_CHILD(parent, 0, "sbp", device_get_unit(parent)); @@ -346,7 +347,7 @@ device_t pa;

SBP_DEBUG(0) - printf("sbp_probe\n"); + printf("%s\n", __func__); END_DEBUG

pa = device_get_parent(dev); @@ -364,36 +365,35 @@ return (0); }

+/* + * Display device characteristics on the console + */ static void -sbp_show_sdev_info(struct sbp_dev *sdev, int new) +sbp_show_sdev_info(struct sbp_dev *sdev) { struct fw_device *fwdev;

- printf("%s:%d:%d ", - device_get_nameunit(sdev->target->sbp->fd.dev), - sdev->target->target_id, - sdev->lun_id - ); - if (new == 2) { - return; - } fwdev = sdev->target->fwdev; - printf("ordered:%d type:%d EUI:%08x%08x node:%d " - "speed:%d maxrec:%d", + device_printf(sdev->target->sbp->fd.dev, + "%s: %s: ordered:%d type:%d EUI:%08x%08x node:%d " + "speed:%d maxrec:%d\n", + __func__, + sdev->bustgtlun, (sdev->type & 0x40) >> 6, (sdev->type & 0x1f), fwdev->eui.hi, fwdev->eui.lo, fwdev->dst, fwdev->speed, - fwdev->maxrec - ); - if (new) - printf(" new!\n"); - else - printf("\n"); - sbp_show_sdev_info(sdev, 2); - printf("'%s' '%s' '%s'\n", sdev->vendor, sdev->product, sdev->revision); + fwdev->maxrec); + + device_printf(sdev->target->sbp->fd.dev, + "%s:%s '%s' '%s' '%s'\n", + __func__, + sdev->bustgtlun, + sdev->vendor, + sdev->product, + sdev->revision); }

static struct { @@ -467,14 +467,16 @@ break; lun = reg->val & 0xffff; SBP_DEBUG(0) - printf("target %d lun %d found\n", target->target_id, lun); + device_printf(sbp->fd.dev, "%s: target %d lun %d found\n", + __func__, target->target_id, lun); END_DEBUG if (maxlun < lun) maxlun = lun; crom_next(&cc); } if (maxlun < 0) - printf("%s:%d no LUN found\n", + device_printf(sbp->fd.dev, "%s: %s:%d no LUN found\n", + __func__, device_get_nameunit(target->sbp->fd.dev), target->target_id);

@@ -503,7 +505,7 @@ M_SBP, M_NOWAIT | M_ZERO);

if (newluns == NULL) { - printf("%s: realloc failed\n", __func__); + device_printf(sbp->fd.dev, "%s: realloc failed\n", __func__); newluns = target->luns; maxlun = target->num_lun; } @@ -530,7 +532,8 @@ break; lun = reg->val & 0xffff; if (lun >= SBP_NUM_LUNS) { - printf("too large lun %d\n", lun); + device_printf(sbp->fd.dev, "%s: too large lun %d\n", + __func__, lun); goto next; }

@@ -539,16 +542,23 @@ sdev = malloc(sizeof(struct sbp_dev), M_SBP, M_NOWAIT | M_ZERO); if (sdev == NULL) { - printf("%s: malloc failed\n", __func__); + device_printf(sbp->fd.dev, "%s: malloc failed\n", __func__); goto next; } target->luns[lun] = sdev; sdev->lun_id = lun; sdev->target = target; STAILQ_INIT(&sdev->ocbs); - CALLOUT_INIT(&sdev->login_callout); + callout_init_mtx(&sdev->login_callout, + &sdev->target->sbp->mtx, + 0); sdev->status = SBP_DEV_RESET; new = 1; + snprintf(sdev->bustgtlun, 32, "%s:%d:%d", + device_get_nameunit(sdev->target->sbp->fd.dev), + sdev->target->target_id, + sdev->lun_id); + } sdev->flags |= VALID_LUN; sdev->type = (reg->val & 0xff0000) >> 16; @@ -560,8 +570,8 @@ /* alignment */ sizeof(uint32_t), SBP_DMA_SIZE, &sdev->dma, BUS_DMA_NOWAIT); if (sdev->dma.v_addr == NULL) { - printf("%s: dma space allocation failed\n", - __func__); + device_printf(sbp->fd.dev, "%s: dma space allocation failed\n", + __func__); free(sdev, M_SBP); target->luns[lun] = NULL; goto next; @@ -581,7 +591,8 @@ + sizeof(struct sbp_ocb) * i + offsetof(struct sbp_ocb, orb[0]); if (bus_dmamap_create(sbp->dmat, 0, &ocb->dmamap)) { - printf("sbp_attach: cannot create dmamap\n"); + device_printf(sbp->fd.dev, "%s: cannot create dmamap\n", + __func__); /* XXX */ goto next; } @@ -604,30 +615,32 @@ static struct sbp_target * sbp_alloc_target(struct sbp_softc *sbp, struct fw_device *fwdev) { - int i; + int new_target_id; struct sbp_target *target; struct crom_context cc; struct csrreg *reg;

SBP_DEBUG(1) - printf("sbp_alloc_target\n"); + device_printf(sbp->fd.dev, "%s: begin\n", __func__); END_DEBUG - i = sbp_new_target(sbp, fwdev); - if (i < 0) { - device_printf(sbp->fd.dev, "increase SBP_NUM_TARGETS!\n"); + new_target_id = sbp_new_target(sbp, fwdev); + if (new_target_id < 0) { + device_printf(sbp->fd.dev, "%s: new_target_id(%d), increase
SBP_NUM_TARGETS!\n", + __func__, new_target_id); return NULL; } /* new target */ - target = &sbp->targets[i]; + target = &sbp->targets[new_target_id]; target->sbp = sbp; target->fwdev = fwdev; - target->target_id = i; + target->target_id = new_target_id; /* XXX we may want to reload mgm port after each bus reset */ /* XXX there might be multiple management agents */ crom_init_context(&cc, target->fwdev->csrrom); reg = crom_search_key(&cc, CROM_MGM); if (reg == NULL || reg->val == 0) { - printf("NULL management address\n"); + device_printf(sbp->fd.dev, "%s: NULL management address\n", + __func__); target->fwdev = NULL; return NULL; } @@ -635,12 +648,16 @@ target->mgm_lo = 0xf0000000 | (reg->val << 2); target->mgm_ocb_cur = NULL; SBP_DEBUG(1) - printf("target:%d mgm_port: %x\n", i, target->mgm_lo); + device_printf(sbp->fd.dev, "%s: target:%d mgm_port: %x\n", + __func__, + target->target_id, target->mgm_lo); END_DEBUG STAILQ_INIT(&target->xferlist); target->n_xfer = 0; STAILQ_INIT(&target->mgm_ocb_queue); - CALLOUT_INIT(&target->mgm_ocb_timeout); + callout_init_mtx(&target->mgm_ocb_timeout, + &sbp->mtx, + 0); CALLOUT_INIT(&target->scan_callout);

target->luns = NULL; @@ -685,29 +702,50 @@ sbp_login_callout(void *arg) { struct sbp_dev *sdev = (struct sbp_dev *)arg; + + mtx_assert(&sdev->target->sbp->mtx, MA_OWNED); sbp_mgm_orb(sdev, ORB_FUN_LGI, NULL); }

+/* + * Login to the SBP capable device + * after the sysctl controlled login_delay + * variable. If the last bus reset occured + * more than login_delay ms in the past + * set ticks to 0 and setup the handler + */ static void sbp_login(struct sbp_dev *sdev) { struct timeval delta; - struct timeval t; - int ticks = 0; + struct timeval tv_login_delay; + int ticks;

+ SBP_LOCK(sdev->target->sbp); + microtime(&delta); timevalsub(&delta, &sdev->target->sbp->last_busreset); - t.tv_sec = login_delay / 1000; - t.tv_usec = (login_delay % 1000) * 1000; - timevalsub(&t, &delta); - if (t.tv_sec >= 0 && t.tv_usec > 0) - ticks = (t.tv_sec * 1000 + t.tv_usec / 1000) * hz / 1000; + tv_login_delay.tv_sec = login_delay / 1000; + tv_login_delay.tv_usec = (login_delay % 1000) * 1000; + timevalsub(&tv_login_delay, &delta); + if (tv_login_delay.tv_sec >= 0 && tv_login_delay.tv_usec > 0) { + ticks = (tv_login_delay.tv_sec * 1000 + tv_login_delay.tv_usec / 1000) * hz /
1000; + } else { + ticks = 0; + } SBP_DEBUG(0) - printf("%s: sec = %jd usec = %ld ticks = %d\n", __func__, - (intmax_t)t.tv_sec, t.tv_usec, ticks); + device_printf(sdev->target->sbp->fd.dev, + "%s: sec = %d, usec = %ld, ticks = %d\n", + __func__, tv_login_delay.tv_sec, tv_login_delay.tv_usec, ticks); + device_printf(sdev->target->sbp->fd.dev, + "%s: tv_login_delay(%d), " + "delta(%d), last_busreset(%d)\n", + __func__, tvtohz(&tv_login_delay), + tvtohz(&delta), tvtohz(&sdev->target->sbp->last_busreset)); END_DEBUG callout_reset(&sdev->login_callout, ticks, sbp_login_callout, (void *)(sdev)); + SBP_UNLOCK(sdev->target->sbp); }

#define SBP_FWDEV_ALIVE(fwdev) (((fwdev)->status == FWDEVATTACHED) \ @@ -717,20 +755,17 @@ sbp_probe_target(void *arg) { struct sbp_target *target = (struct sbp_target *)arg; - struct sbp_softc *sbp; + struct sbp_softc *sbp = target->sbp; struct sbp_dev *sdev; - struct firewire_comm *fc; int i, alive;

alive = SBP_FWDEV_ALIVE(target->fwdev); SBP_DEBUG(1) - printf("sbp_probe_target %d\n", target->target_id); - if (!alive) - printf("not alive\n"); + device_printf(sbp->fd.dev, "%s %d%salive\n", + __func__, target->target_id, + (!alive) ? " not " : ""); END_DEBUG

- sbp = target->sbp; - fc = target->sbp->fd.fc; sbp_alloc_lun(target);

/* XXX untimeout mgm_ocb and dequeue */ @@ -747,8 +782,9 @@ } sbp_probe_lun(sdev); SBP_DEBUG(0) - sbp_show_sdev_info(sdev, - (sdev->status == SBP_DEV_RESET)); + SBP_LOCK(sbp); + sbp_show_sdev_info(sdev); + SBP_UNLOCK(sbp); END_DEBUG

sbp_abort_all_ocbs(sdev, CAM_SCSI_BUS_RESET); @@ -763,7 +799,9 @@ case SBP_DEV_ATTACHED: case SBP_DEV_RETRY: default: + SBP_LOCK(sbp); sbp_mgm_orb(sdev, ORB_FUN_RCN, NULL); + SBP_UNLOCK(sbp); break; } } else { @@ -771,8 +809,8 @@ case SBP_DEV_ATTACHED: SBP_DEBUG(0) /* the device has gone */ - sbp_show_sdev_info(sdev, 2); - printf("lost target\n"); + device_printf(sbp->fd.dev, "%s: lost target\n", + __func__); END_DEBUG if (sdev->path) { SBP_LOCK(sbp); @@ -805,7 +843,7 @@

sbp = (struct sbp_softc *)arg; SBP_DEBUG(0) - printf("sbp_post_busreset\n"); + device_printf(sbp->fd.dev,"%s\n", __func__); END_DEBUG if ((sbp->sim->flags & SIMQ_FREEZED) == 0) { SBP_LOCK(sbp); @@ -825,7 +863,8 @@ int i, alive;

SBP_DEBUG(0) - printf("sbp_post_explore (sbp_cold=%d)\n", sbp_cold); + device_printf(sbp->fd.dev, "%s: (sbp_cold=%d)\n", + __func__, sbp_cold); END_DEBUG /* We need physical access */ if (!firewire_phydma_enable) @@ -857,12 +896,10 @@ /* traverse device list */ STAILQ_FOREACH(fwdev, &sbp->fd.fc->devices, link) { SBP_DEBUG(0) - printf("sbp_post_explore: EUI:%08x%08x ", - fwdev->eui.hi, fwdev->eui.lo); - if (fwdev->status != FWDEVATTACHED) - printf("not attached, state=%d.\n", fwdev->status); - else - printf("attached\n"); + device_printf(sbp->fd.dev,"%s:: EUI:%08x%08x %s attached, state=%d\n", + __func__, fwdev->eui.hi, fwdev->eui.lo, + (fwdev->status != FWDEVATTACHED) ? "not" : "", + fwdev->status); END_DEBUG alive = SBP_FWDEV_ALIVE(fwdev); for(i = 0 ; i < SBP_NUM_TARGETS ; i ++){ @@ -899,8 +936,7 @@ struct sbp_dev *sdev; sdev = (struct sbp_dev *)xfer->sc; SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("sbp_loginres_callback\n"); + device_printf(sdev->target->sbp->fd.dev,"%s\n", __func__); END_DEBUG /* recycle */ s = splfw(); @@ -933,8 +969,8 @@ int i;

if (xfer->resp != 0) { - sbp_show_sdev_info(sdev, 2); - printf("sbp_reset_start failed: resp=%d\n", xfer->resp); + device_printf(sdev->target->sbp->fd.dev, + "%s: %s failed: resp=%d\n", __func__, sdev->bustgtlun, xfer->resp); }

for (i = 0; i < target->num_lun; i++) { @@ -951,8 +987,8 @@ struct fw_pkt *fp;

SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("sbp_reset_start\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__,sdev->bustgtlun); END_DEBUG

xfer = sbp_write_cmd(sdev, FWTCODE_WREQQ, 0); @@ -973,18 +1009,11 @@ sdev = (struct sbp_dev *)xfer->sc;

SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("sbp_mgm_callback\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG resp = xfer->resp; sbp_xfer_free(xfer); -#if 0 - if (resp != 0) { - sbp_show_sdev_info(sdev, 2); - printf("management ORB failed(%d) ... RESET_START\n", resp); - sbp_reset_start(sdev); - } -#endif return; }

@@ -1011,14 +1040,14 @@ sdev = (struct sbp_dev *) ccb->ccb_h.ccb_sdev_ptr; target = sdev->target; SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("sbp_cam_scan_lun\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG if ((ccb->ccb_h.status & CAM_STATUS_MASK) == CAM_REQ_CMP) { sdev->status = SBP_DEV_ATTACHED; } else { - sbp_show_sdev_info(sdev, 2); - printf("scan failed\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s failed\n", __func__, sdev->bustgtlun); } sdev = sbp_next_dev(target, sdev->lun_id + 1); if (sdev == NULL) { @@ -1047,8 +1076,8 @@ return; } SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("sbp_cam_scan_target\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG ccb = malloc(sizeof(union ccb), M_SBP, M_NOWAIT | M_ZERO); if (ccb == NULL) { @@ -1089,8 +1118,8 @@ target = sdev->target; sbp = target->sbp; SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("sbp_do_attach\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG sbp_xfer_free(xfer);

@@ -1120,12 +1149,12 @@

sdev = (struct sbp_dev *)xfer->sc; SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("%s\n", __func__); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG if (xfer->resp != 0) { - sbp_show_sdev_info(sdev, 2); - printf("%s: resp=%d\n", __func__, xfer->resp); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s resp=%d\n", __func__, sdev->bustgtlun, xfer->resp); }

sbp_xfer_free(xfer); @@ -1144,8 +1173,8 @@ struct fw_pkt *fp;

SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("sbp_agent_reset\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG xfer = sbp_write_cmd(sdev, FWTCODE_WREQQ, 0x04); if (xfer == NULL) @@ -1167,8 +1196,8 @@

sdev = (struct sbp_dev *)xfer->sc; SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("sbp_busy_timeout_callback\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG sbp_xfer_free(xfer); sbp_agent_reset(sdev); @@ -1180,8 +1209,8 @@ struct fw_pkt *fp; struct fw_xfer *xfer; SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("sbp_busy_timeout\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG xfer = sbp_write_cmd(sdev, FWTCODE_WREQQ, 0);

@@ -1200,8 +1229,8 @@ sdev = (struct sbp_dev *)xfer->sc;

SBP_DEBUG(2) - sbp_show_sdev_info(sdev, 2); - printf("%s\n", __func__); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG if (xfer->resp != 0) { /* XXX */ @@ -1230,8 +1259,10 @@ struct fw_xfer *xfer; struct fw_pkt *fp; SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("%s: 0x%08x\n", __func__, (uint32_t)ocb->bus_addr); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s 0x%08x\n", + __func__, sdev->bustgtlun, + (uint32_t)ocb->bus_addr); END_DEBUG

mtx_assert(&sdev->target->sbp->mtx, MA_OWNED); @@ -1278,12 +1309,13 @@ sdev = (struct sbp_dev *)xfer->sc;

SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("sbp_doorbell_callback\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG if (xfer->resp != 0) { /* XXX */ - printf("%s: xfer->resp = %d\n", __func__, xfer->resp); + device_printf(sdev->target->sbp->fd.dev, + "%s: xfer->resp = %d\n", __func__, xfer->resp); } sbp_xfer_free(xfer); sdev->flags &= ~ORB_DOORBELL_ACTIVE; @@ -1302,8 +1334,8 @@ struct fw_xfer *xfer; struct fw_pkt *fp; SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("sbp_doorbell\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG

if ((sdev->flags & ORB_DOORBELL_ACTIVE) != 0) { @@ -1335,19 +1367,25 @@ xfer = STAILQ_FIRST(&target->xferlist); if (xfer == NULL) { if (target->n_xfer > 5 /* XXX */) { - printf("sbp: no more xfer for this target\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s: no more xfer for this target\n", + __func__); splx(s); return(NULL); } xfer = fw_xfer_alloc_buf(M_SBP, 8, 0); if(xfer == NULL){ - printf("sbp: fw_xfer_alloc_buf failed\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s: fw_xfer_alloc_buf failed\n", + __func__); splx(s); return NULL; } target->n_xfer ++; if (debug) - printf("sbp: alloc %d xfer\n", target->n_xfer); + device_printf(sdev->target->sbp->fd.dev, + "%s: alloc %d xfer\n", + __func__, target->n_xfer); new = 1; } else { STAILQ_REMOVE_HEAD(&target->xferlist, link); @@ -1398,31 +1436,24 @@ struct fw_pkt *fp; struct sbp_ocb *ocb; struct sbp_target *target; - int s, nid; + int nid;

+ mtx_assert(&sdev->target->sbp->mtx, MA_OWNED); target = sdev->target; nid = target->sbp->fd.fc->nodeid | FWLOCALBUS;

- s = splfw(); - SBP_LOCK(target->sbp); if (func == ORB_FUN_RUNQUEUE) { ocb = STAILQ_FIRST(&target->mgm_ocb_queue); if (target->mgm_ocb_cur != NULL || ocb == NULL) { - SBP_UNLOCK(target->sbp); - splx(s); return; } STAILQ_REMOVE_HEAD(&target->mgm_ocb_queue, ocb); - SBP_UNLOCK(target->sbp); goto start; } if ((ocb = sbp_get_ocb(sdev)) == NULL) { - SBP_UNLOCK(target->sbp); - splx(s); /* XXX */ return; } - SBP_UNLOCK(target->sbp); ocb->flags = OCB_ACT_MGM; ocb->sdev = sdev;

@@ -1431,8 +1462,10 @@ ocb->orb[7] = htonl(SBP_DEV2ADDR(target->target_id, sdev->lun_id));

SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("%s\n", orb_fun_name[(func>>16)&0xf]); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s %s\n", + __func__,sdev->bustgtlun, + orb_fun_name[(func>>16)&0xf]); END_DEBUG switch (func) { case ORB_FUN_LGI: @@ -1460,19 +1493,16 @@

if (target->mgm_ocb_cur != NULL) { /* there is a standing ORB */ - SBP_LOCK(target->sbp); STAILQ_INSERT_TAIL(&sdev->target->mgm_ocb_queue, ocb, ocb); - SBP_UNLOCK(target->sbp); - splx(s); return; } start: target->mgm_ocb_cur = ocb; - splx(s);

callout_reset(&target->mgm_ocb_timeout, 5*hz, sbp_mgm_timeout, (caddr_t)ocb); - xfer = sbp_write_cmd(sdev, FWTCODE_WREQB, 0); + + xfer = sbp_write_cmd_locked(sdev, FWTCODE_WREQB, 0); if(xfer == NULL){ return; } @@ -1485,12 +1515,10 @@ fp->mode.wreqb.extcode = 0; xfer->send.payload[0] = htonl(nid << 16); xfer->send.payload[1] = htonl(ocb->bus_addr & 0xffffffff); -SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("mgm orb: %08x\n", (uint32_t)ocb->bus_addr); -END_DEBUG

+ SBP_UNLOCK(sdev->target->sbp); fw_asyreq(xfer->fc, -1, xfer); + SBP_LOCK(sdev->target->sbp); }

static void @@ -1532,8 +1560,8 @@ SBP_DEBUG(0) sbp_print_scsi_cmd(ocb); /* XXX need decode status */ - sbp_show_sdev_info(ocb->sdev, 2); - printf("SCSI status %x sfmt %x valid %x key %x code %x qlfr %x len %d\n", + printf("%s: SCSI status %x sfmt %x valid %x key %x code %x qlfr %x len %d\n", + ocb->sdev->bustgtlun, sbp_cmd_status->status, sbp_cmd_status->sfmt, sbp_cmd_status->valid, @@ -1601,9 +1629,10 @@ */ break; default: - sbp_show_sdev_info(ocb->sdev, 2); - printf("sbp_scsi_status: unknown scsi status 0x%x\n", - sbp_cmd_status->status); + device_printf(ocb->sdev->target->sbp->fd.dev, + "%s:%s unknown scsi status 0x%x\n", + __func__, ocb->sdev->bustgtlun, + sbp_cmd_status->status); } }

@@ -1620,8 +1649,8 @@ if (ccb->csio.cdb_io.cdb_bytes[1] & SI_EVPD) return; SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); - printf("sbp_fix_inq_data\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s\n", __func__, sdev->bustgtlun); END_DEBUG inq = (struct scsi_inquiry_data *) ccb->csio.data_ptr; switch (SID_TYPE(inq)) { @@ -1723,30 +1752,35 @@ ocb = target->mgm_ocb_cur; if (ocb != NULL) { if (OCB_MATCH(ocb, sbp_status)) { + SBP_LOCK(sdev->target->sbp); callout_stop(&target->mgm_ocb_timeout); + SBP_UNLOCK(sdev->target->sbp); target->mgm_ocb_cur = NULL; break; } } ocb = sbp_dequeue_ocb(sdev, sbp_status); if (ocb == NULL) { - sbp_show_sdev_info(sdev, 2); + device_printf(sdev->target->sbp->fd.dev, #if defined(__DragonFly__) || __FreeBSD_version < 500000 - printf("No ocb(%lx) on the queue\n", + "%s:%s No ocb(%lx) on the queue\n", #else - printf("No ocb(%x) on the queue\n", + "%s:%s No ocb(%x) on the queue\n", #endif - ntohl(sbp_status->orb_lo)); + __func__,sdev->bustgtlun, + ntohl(sbp_status->orb_lo)); } break; case 2: /* unsolicit */ - sbp_show_sdev_info(sdev, 2); - printf("unsolicit status received\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s unsolicit status received\n", + __func__, sdev->bustgtlun); break; default: - sbp_show_sdev_info(sdev, 2); - printf("unknown sbp_status->src\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s unknown sbp_status->src\n", + __func__, sdev->bustgtlun); }

status_valid0 = (sbp_status->src < 2 @@ -1757,18 +1791,20 @@ if (!status_valid0 || debug > 2){ int status; SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("ORB status src:%x resp:%x dead:%x" + device_printf(sdev->target->sbp->fd.dev, + "%s:%s ORB status src:%x resp:%x dead:%x" #if defined(__DragonFly__) || __FreeBSD_version < 500000 " len:%x stat:%x orb:%x%08lx\n", #else " len:%x stat:%x orb:%x%08x\n", #endif + __func__, sdev->bustgtlun, sbp_status->src, sbp_status->resp, sbp_status->dead, sbp_status->len, sbp_status->status, ntohs(sbp_status->orb_hi), ntohl(sbp_status->orb_lo)); END_DEBUG - sbp_show_sdev_info(sdev, 2); + device_printf(sdev->target->sbp->fd.dev, + "%s\n", sdev->bustgtlun); status = sbp_status->status; switch(sbp_status->resp) { case 0: @@ -1827,14 +1863,19 @@ login_res->cmd_lo = ntohl(login_res->cmd_lo); if (status_valid) { SBP_DEBUG(0) -sbp_show_sdev_info(sdev, 2); -printf("login: len %d, ID %d, cmd %08x%08x, recon_hold %d\n", login_res->len,
login_res->id, login_res->cmd_hi, login_res->cmd_lo,
ntohs(login_res->recon_hold)); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s login: len %d, ID %d, cmd %08x%08x, recon_hold %d\n", + __func__, sdev->bustgtlun, + login_res->len, login_res->id, + login_res->cmd_hi, login_res->cmd_lo, + ntohs(login_res->recon_hold)); END_DEBUG sbp_busy_timeout(sdev); } else { /* forgot logout? */ - sbp_show_sdev_info(sdev, 2); - printf("login failed\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s login failed\n", + __func__, sdev->bustgtlun); sdev->status = SBP_DEV_RESET; } break; @@ -1842,23 +1883,22 @@ login_res = sdev->login; if (status_valid) { SBP_DEBUG(0) -sbp_show_sdev_info(sdev, 2); -printf("reconnect: len %d, ID %d, cmd %08x%08x\n", login_res->len,
login_res->id, login_res->cmd_hi, login_res->cmd_lo); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s reconnect: len %d, ID %d, cmd %08x%08x\n", + __func__, sdev->bustgtlun, + login_res->len, login_res->id, + login_res->cmd_hi, login_res->cmd_lo); END_DEBUG -#if 1 if (sdev->status == SBP_DEV_ATTACHED) sbp_scan_dev(sdev); else sbp_agent_reset(sdev); -#else - sdev->status = SBP_DEV_ATTACHED; - sbp_mgm_orb(sdev, ORB_FUN_ATS, NULL); -#endif } else { /* reconnection hold time exceed? */ SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); - printf("reconnect failed\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s reconnect failed\n", + __func__, sdev->bustgtlun); END_DEBUG sbp_login(sdev); } @@ -1875,25 +1915,20 @@ sbp_agent_reset(sdev); break; default: - sbp_show_sdev_info(sdev, 2); - printf("unknown function %d\n", orb_fun); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s unknown function %d\n", + __func__, sdev->bustgtlun, orb_fun); break; } + SBP_LOCK(sbp); sbp_mgm_orb(sdev, ORB_FUN_RUNQUEUE, NULL); + SBP_UNLOCK(sbp); break; case OCB_ACT_CMD: sdev->timeout = 0; if(ocb->ccb != NULL){ union ccb *ccb; -/* - uint32_t *ld; - ld = ocb->ccb->csio.data_ptr; - if(ld != NULL && ocb->ccb->csio.dxfer_len != 0) - printf("ptr %08x %08x %08x %08x\n", ld[0], ld[1], ld[2], ld[3]); - else - printf("ptr NULL\n"); -printf("len %d\n", sbp_status->len); -*/ + ccb = ocb->ccb; if(sbp_status->len > 1){ sbp_scsi_status(sbp_status, ocb); @@ -2101,10 +2136,13 @@ sdev = target->luns[j]; if (sdev == NULL) continue; + SBP_LOCK(sdev->target->sbp); callout_stop(&sdev->login_callout); - if (sdev->status >= SBP_DEV_TOATTACH && - sdev->status <= SBP_DEV_ATTACHED) + if (sdev->status >= SBP_DEV_TOATTACH && + sdev->status <= SBP_DEV_ATTACHED) { sbp_mgm_orb(sdev, ORB_FUN_LGO, NULL); + } + SBP_UNLOCK(sdev->target->sbp); } }

@@ -2144,8 +2182,10 @@

if (target->luns == NULL) return; + sbp = target->sbp; + SBP_LOCK(sbp); callout_stop(&target->mgm_ocb_timeout); - sbp = target->sbp; + SBP_UNLOCK(sbp); for (i = 0; i < target->num_lun; i++) sbp_free_sdev(target->luns[i]);

@@ -2261,11 +2301,13 @@ } switch(method) { case 1: - printf("target reset\n"); + device_printf(sdev->target->sbp->fd.dev,"target reset\n"); + SBP_LOCK(sdev->target->sbp); sbp_mgm_orb(sdev, ORB_FUN_RST, NULL); + SBP_UNLOCK(sdev->target->sbp); break; case 2: - printf("reset start\n"); + device_printf(sdev->target->sbp->fd.dev,"reset start\n"); sbp_reset_start(sdev); break; } @@ -2279,20 +2321,18 @@ struct sbp_dev *sdev = ocb->sdev; struct sbp_target *target = sdev->target;

- sbp_show_sdev_info(sdev, 2); - printf("request timeout(mgm orb:0x%08x) ... ", - (uint32_t)ocb->bus_addr); + mtx_assert(&sdev->target->sbp->mtx, MA_OWNED); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s request timeout(mgm orb:0x%08x)\n", + __func__, sdev->bustgtlun, (uint32_t)ocb->bus_addr); target->mgm_ocb_cur = NULL; + SBP_UNLOCK(sdev->target->sbp); sbp_free_ocb(sdev, ocb); -#if 0 - /* XXX */ - printf("run next request\n"); - sbp_mgm_orb(sdev, ORB_FUN_RUNQUEUE, NULL); -#endif -#if 1 - printf("reset start\n"); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s run next request\n", + __func__, sdev->bustgtlun); sbp_reset_start(sdev); -#endif + SBP_LOCK(sdev->target->sbp); }

static void @@ -2301,9 +2341,9 @@ struct sbp_ocb *ocb = (struct sbp_ocb *)arg; struct sbp_dev *sdev = ocb->sdev;

- sbp_show_sdev_info(sdev, 2); - printf("request timeout(cmd orb:0x%08x) ... ", - (uint32_t)ocb->bus_addr); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s request timeout(cmd orb:0x%08x) ... ", + __func__, sdev->bustgtlun, (uint32_t)ocb->bus_addr);

sdev->timeout ++; switch(sdev->timeout) { @@ -2760,13 +2800,13 @@ int flags;

SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); + device_printf(sdev->target->sbp->fd.dev, #if defined(__DragonFly__) || __FreeBSD_version < 500000 - printf("%s: 0x%08lx src %d\n", + "%s:%s 0x%08lx src %d\n", #else - printf("%s: 0x%08x src %d\n", + "%s:%s 0x%08x src %d\n", #endif - __func__, ntohl(sbp_status->orb_lo), sbp_status->src); + __func__, sdev->bustgtlun, ntohl(sbp_status->orb_lo), sbp_status->src); END_DEBUG SBP_LOCK(sdev->target->sbp); for (ocb = STAILQ_FIRST(&sdev->ocbs); ocb != NULL; ocb = next) { @@ -2823,8 +2863,9 @@ splx(s); SBP_DEBUG(0) if (ocb && order > 0) { - sbp_show_sdev_info(sdev, 2); - printf("unordered execution order:%d\n", order); + device_printf(sdev->target->sbp->fd.dev, + "%s:%s unordered execution order:%d\n", + __func__, sdev->bustgtlun, order); } END_DEBUG return (ocb); @@ -2838,11 +2879,11 @@

mtx_assert(&sdev->target->sbp->mtx, MA_OWNED); SBP_DEBUG(1) - sbp_show_sdev_info(sdev, 2); + device_printf(sdev->target->sbp->fd.dev, #if defined(__DragonFly__) || __FreeBSD_version < 500000 - printf("%s: 0x%08x\n", __func__, ocb->bus_addr); + "%s:%s 0x%08x\n", __func__, sdev->bustgtlun, ocb->bus_addr); #else - printf("%s: 0x%08jx\n", __func__, (uintmax_t)ocb->bus_addr); + "%s:%s 0x%08jx\n", __func__, sdev->bustgtlun, (uintmax_t)ocb->bus_addr); #endif END_DEBUG prev2 = prev = STAILQ_LAST(&sdev->ocbs, sbp_ocb, ocb); @@ -2924,11 +2965,11 @@

sdev = ocb->sdev; SBP_DEBUG(0) - sbp_show_sdev_info(sdev, 2); + device_printf(sdev->target->sbp->fd.dev, #if defined(__DragonFly__) || __FreeBSD_version < 500000 - printf("sbp_abort_ocb 0x%x\n", ocb->bus_addr); + "%s:%s 0x%x\n", __func__, sdev->bustgtlun, ocb->bus_addr); #else - printf("sbp_abort_ocb 0x%jx\n", (uintmax_t)ocb->bus_addr); + "%s:%s 0x%jx\n", __func__, sdev->bustgtlun, (uintmax_t)ocb->bus_addr); #endif END_DEBUG SBP_DEBUG(1)