More methodical progress?

Index: firewire.c
===================================================================
--- firewire.c	(revision 188705)
+++ firewire.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/firewire.c 188704 2009-02-17 04:08:08Z sbruno $
  *
  */
 
@@ -1257,12 +1257,11 @@
 	fp->mode.common.tcode |= FWTCODE_PHY;
 
 	if (firewire_debug)
-		printf("send phy_config root_node=%d gap_count=%d\n",
-						root_node, gap_count);
+		device_printf(fc->bdev, "%s: root_node=%d gap_count=%d\n",
+					__func__, root_node, gap_count);
 	fw_asyreq(fc, -1, xfer);
 }
 
-#if 0
 /*
  * Dump self ID. 
  */
@@ -1278,7 +1277,6 @@
 		s->p0.power_class, s->p0.port0, s->p0.port1,
 		s->p0.port2, s->p0.initiated_reset, s->p0.more_packets);
 }
-#endif
 
 /*
  * To receive self ID. 
@@ -1302,7 +1300,8 @@
 	self_id = &fc->topology_map->self_id[0];
 	for(i = 0; i < fc->sid_cnt; i ++){
 		if (sid[1] != ~sid[0]) {
-			printf("fw_sidrcv: invalid self-id packet\n");
+			device_printf(fc->bdev, "%s: ERROR invalid self-id packet\n",
+						__func__);
 			sid += 2;
 			continue;
 		}
@@ -1311,9 +1310,8 @@
 		if(self_id->p0.sequel == 0){
 			fc->topology_map->node_count ++;
 			c_port = 0;
-#if 0
-			fw_print_sid(sid[0]);
-#endif
+			if (firewire_debug)
+				fw_print_sid(sid[0]);
 			node = self_id->p0.phy_id;
 			if(fc->max_node < node){
 				fc->max_node = self_id->p0.phy_id;
@@ -1348,7 +1346,6 @@
 		self_id++;
 		fc->topology_map->self_id_count ++;
 	}
-	device_printf(fc->bdev, "%d nodes", fc->max_node + 1);
 	/* CRC */
 	fc->topology_map->crc = fw_crc16(
 			(uint32_t *)&fc->topology_map->generation,
@@ -1367,16 +1364,11 @@
 	bcopy(p, &CSRARC(fc, SPED_MAP + 8), (fc->speed_map->crc_len - 1)*4);
 
 	fc->max_hop = fc->max_node - i_branch;
-	printf(", maxhop <= %d", fc->max_hop);
-		
-	if(fc->irm == -1 ){
-		printf(", Not found IRM capable node");
-	}else{
-		printf(", cable IRM = %d", fc->irm);
-		if (fc->irm == fc->nodeid)
-			printf(" (me)");
-	}
-	printf("\n");
+	device_printf(fc->bdev, "%d nodes, maxhop <= %d %s irm(%d) %s\n",
+			fc->max_node + 1, fc->max_hop,
+			(fc->irm == -1) ? "Not IRM capable" : "cable IRM",
+			fc->irm,
+			(fc->irm == fc->nodeid) ? " (me) " : "");
 
 	if (try_bmr && (fc->irm != -1) && (CSRARC(fc, BUS_MGR_ID) == 0x3f)) {
 		if (fc->irm == fc->nodeid) {
@@ -1408,10 +1400,23 @@
 	fc->status = FWBUSEXPLORE;
 
 	/* Invalidate all devices, just after bus reset. */
+	if (firewire_debug)
+		device_printf(fc->bdev, "%s:"
+			"iterate and invalidate all nodes\n",
+			__func__);
 	STAILQ_FOREACH(fwdev, &fc->devices, link)
 		if (fwdev->status != FWDEVINVAL) {
 			fwdev->status = FWDEVINVAL;
 			fwdev->rcnt = 0;
+			if (firewire_debug)
+				device_printf(fc->bdev, "%s:"
+					"Invalidate Dev ID: %08x%08x\n",
+					__func__, fwdev->eui.hi, fwdev->eui.lo);
+		} else {
+			if (firewire_debug)
+				device_printf(fc->bdev, "%s:"
+					"Dev ID: %08x%08x already invalid\n",
+					__func__, fwdev->eui.hi, fwdev->eui.lo);
 		}
 	splx(s);
 
@@ -1420,13 +1425,13 @@
 
 static int
 fw_explore_read_quads(struct fw_device *fwdev, int offset,
-    uint32_t *quad, int n)
+    uint32_t *quad, int length)
 {
 	struct fw_xfer *xfer;
 	uint32_t tmp;
 	int i, error;
 
-	for (i = 0; i < n; i ++, offset += sizeof(uint32_t)) {
+	for (i = 0; i < length; i ++, offset += sizeof(uint32_t)) {
 		xfer = fwmem_read_quad(fwdev, NULL, -1,
 		    0xffff, 0xf0000000 | offset, (void *)&tmp,
 		    fw_xferwake);
@@ -1521,20 +1526,25 @@
 	hdr = (struct csrhdr *)&csr[0];
 	if (hdr->info_len != 4) {
 		if (firewire_debug)
-			printf("node%d: wrong bus info len(%d)\n",
-			    node, hdr->info_len);
+			device_printf(fc->bdev, "%s: node%d: wrong bus info len(%d)\n",
+			    __func__, node, hdr->info_len);
+		dfwdev->status = FWDEVINVAL;
 		return (-1);
 	}
 
 	/* bus info */
 	err = fw_explore_read_quads(dfwdev, CSRROMOFF + 0x04, &csr[1], 4);
-	if (err)
+	if (err) {
+		device_printf(fc->bdev, "%s: node%d: error reading 0x04\n",
+		    __func__, node);
+		dfwdev->status = FWDEVINVAL;
 		return (-1);
+	}
 	binfo = (struct bus_info *)&csr[1];
 	if (binfo->bus_name != CSR_BUS_NAME_IEEE1394) {
-		if (firewire_debug)
-			printf("node%d: invalid bus name 0x%08x\n",
-			    node, binfo->bus_name);
+		device_printf(fc->bdev, "%s: node%d: invalid bus name 0x%08x\n",
+		    __func__, node, binfo->bus_name);
+		dfwdev->status = FWDEVINVAL;
 		return (-1);
 	}
 
@@ -1557,8 +1567,8 @@
 		fwdev = malloc(sizeof(struct fw_device), M_FW,
 						M_NOWAIT | M_ZERO);
 		if (fwdev == NULL) {
-			if (firewire_debug)
-				printf("node%d: no memory\n", node);
+			device_printf(fc->bdev, "%s: node%d: no memory\n",
+					__func__, node);
 			return (-1);
 		}
 		fwdev->fc = fc;
@@ -1677,12 +1687,22 @@
 
 	for (node = 0; node <= fc->max_node; node ++) {
 		/* We don't probe myself and linkdown nodes */
-		if (node == fc->nodeid)
+		if (node == fc->nodeid) {
+			if (firewire_debug)
+				device_printf(fc->bdev, "%s:"
+					"found myself node(%d) fc->nodeid(%d) fc->max_node(%d)\n",
+					__func__, node, fc->nodeid, fc->max_node);
 			continue;
+		} else if (firewire_debug) {
+			device_printf(fc->bdev, "%s:"
+				"node(%d) fc->max_node(%d) found\n",
+				__func__, node, fc->max_node);
+		}
 		fwsid = fw_find_self_id(fc, node);
 		if (!fwsid || !fwsid->p0.link_active) {
 			if (firewire_debug)
-				printf("node%d: link down\n", node);
+				device_printf(fc->bdev, "%s: node%d: link down\n",
+							__func__, node);
 			continue;
 		}
 		nodes[todo++] = node;
@@ -1697,8 +1717,8 @@
 			if (err)
 				nodes[todo2++] = nodes[i];
 			if (firewire_debug)
-				printf("%s: node %d, err = %d\n",
-					__FUNCTION__, node, err);
+				device_printf(fc->bdev, "%s: node %d, err = %d\n",
+					__func__, node, err);
 		}
 		todo = todo2;
 	}
@@ -1748,11 +1768,18 @@
 			fwdev->status = FWDEVATTACHED;
 		} else if (fwdev->status == FWDEVINVAL) {
 			fwdev->rcnt ++;
+			if (firewire_debug)
+				device_printf(fc->bdev, "%s:"
+					"fwdev->rcnt(%d), hold_count(%d)\n",
+					__func__, fwdev->rcnt, hold_count);
 			if (fwdev->rcnt > hold_count) {
 				/*
 				 * Remove devices which have not been seen
 				 * for a while.
 				 */
+				device_printf(fc->bdev, "%s:"
+					"Removing missing device ID:%08x%08x\n",
+					__func__, fwdev->eui.hi, fwdev->eui.lo);
 				STAILQ_REMOVE(&fc->devices, fwdev, fw_device,
 				    link);
 				free(fwdev, M_FW);
@@ -1761,16 +1788,16 @@
 	}
 
 	err = device_get_children(fc->bdev, &devlistp, &devcnt);
-	if( err != 0 )
-		return;
-	for( i = 0 ; i < devcnt ; i++){
-		if (device_get_state(devlistp[i]) >= DS_ATTACHED)  {
-			fdc = device_get_softc(devlistp[i]);
-			if (fdc->post_explore != NULL)
-				fdc->post_explore(fdc);
+	if( err == 0 ) {
+		for( i = 0 ; i < devcnt ; i++){
+			if (device_get_state(devlistp[i]) >= DS_ATTACHED)  {
+				fdc = device_get_softc(devlistp[i]);
+				if (fdc->post_explore != NULL)
+					fdc->post_explore(fdc);
+			}
 		}
+		free(devlistp, M_TEMP);
 	}
-	free(devlistp, M_TEMP);
 
 	return;
 }
@@ -1850,8 +1877,9 @@
 	for (i = 0; i < rb->nvec; i++, rb->vec++) {
 		len = MIN(rb->vec->iov_len, plen);
 		if (res < len) {
-			printf("rcv buffer(%d) is %d bytes short.\n",
-			    rb->xfer->recv.pay_len, len - res);
+			device_printf(rb->fc->bdev, "%s:"
+				" rcv buffer(%d) is %d bytes short.\n",
+				__func__, rb->xfer->recv.pay_len, len - res);
 			len = res;
 		}
 		bcopy(rb->vec->iov_base, p, len);
@@ -1898,13 +1926,15 @@
 		rb->xfer = fw_tl2xfer(rb->fc, fp->mode.hdr.src,
 				fp->mode.hdr.tlrt >> 2, fp->mode.hdr.tcode);
 		if(rb->xfer == NULL) {
-			printf("fw_rcv: unknown response "
-			    "%s(%x) src=0x%x tl=0x%x rt=%d data=0x%x\n",
-			    tcode_str[tcode], tcode,
-			    fp->mode.hdr.src,
-			    fp->mode.hdr.tlrt >> 2,
-			    fp->mode.hdr.tlrt & 3,
-			    fp->mode.rresq.data);
+			device_printf(rb->fc->bdev, "%s: "
+				"unknown response "
+			    	"%s(%x) src=0x%x tl=0x%x rt=%d data=0x%x\n",
+				__func__,
+			    	tcode_str[tcode], tcode,
+				fp->mode.hdr.src,
+				fp->mode.hdr.tlrt >> 2,
+				fp->mode.hdr.tlrt & 3,
+				fp->mode.rresq.data);
 #if 0
 			printf("try ad-hoc work around!!\n");
 			rb->xfer = fw_tl2xfer(rb->fc, fp->mode.hdr.src,
@@ -1936,7 +1966,8 @@
 #endif
 			break;
 		default:
-			printf("unexpected flag 0x%02x\n", rb->xfer->flag);
+			device_printf(rb->fc->bdev, "%s: "
+				"unexpected flag 0x%02x\n", __func__, rb->xfer->flag);
 		}
 		return;
 	case FWTCODE_WREQQ:
@@ -1947,17 +1978,23 @@
 		bind = fw_bindlookup(rb->fc, fp->mode.rreqq.dest_hi,
 			fp->mode.rreqq.dest_lo);
 		if(bind == NULL){
-			printf("Unknown service addr 0x%04x:0x%08x %s(%x)"
+			device_printf(rb->fc->bdev, "%s: "
+				"Unknown service addr 0x%04x:0x%08x %s(%x)"
 #if defined(__DragonFly__) || __FreeBSD_version < 500000
-			    " src=0x%x data=%lx\n",
+				" src=0x%x data=%lx\n",
 #else
-			    " src=0x%x data=%x\n",
+				" src=0x%x data=%x\n",
 #endif
-			    fp->mode.wreqq.dest_hi, fp->mode.wreqq.dest_lo,
-			    tcode_str[tcode], tcode,
-			    fp->mode.hdr.src, ntohl(fp->mode.wreqq.data));
+				__func__,
+				fp->mode.wreqq.dest_hi,
+				fp->mode.wreqq.dest_lo,
+				tcode_str[tcode], tcode,
+				fp->mode.hdr.src,
+				ntohl(fp->mode.wreqq.data));
+
 			if (rb->fc->status == FWBUSINIT) {
-				printf("fw_rcv: cannot respond(bus reset)!\n");
+				device_printf(rb->fc->bdev, "%s: cannot respond(bus reset)!\n",
+						__func__);
 				return;
 			}
 			rb->xfer = fw_xfer_alloc(M_FWXFER);
@@ -2003,9 +2040,9 @@
 			len += rb->vec[i].iov_len;
 		rb->xfer = STAILQ_FIRST(&bind->xferlist);
 		if (rb->xfer == NULL) {
-#if 1
-			printf("Discard a packet for this bind.\n");
-#endif
+			device_printf(rb->fc->bdev, "%s: "
+				"Discard a packet for this bind.\n",
+				__func__);
 			return;
 		}
 		STAILQ_REMOVE_HEAD(&bind->xferlist, link);
@@ -2056,7 +2093,8 @@
 	}
 #endif
 	default:
-		printf("fw_rcv: unknow tcode %d\n", tcode);
+		device_printf(rb->fc->bdev,"%s: unknown tcode %d\n",
+				__func__, tcode);
 		break;
 	}
 }
@@ -2229,6 +2267,12 @@
 	return((uint16_t) crc);
 }
 
+/*
+ * Find the root node, if it is not
+ * Cycle Master Capable, then we should
+ * override this and become the Cycle
+ * Master
+ */
 static int
 fw_bmr(struct firewire_comm *fc)
 {
@@ -2253,13 +2297,13 @@
 	} else
 		cmstr = -1;
 
-	device_printf(fc->bdev, "bus manager %d ", CSRARC(fc, BUS_MGR_ID));
+	device_printf(fc->bdev, "bus manager %d %s\n",
+		CSRARC(fc, BUS_MGR_ID),
+		(CSRARC(fc, BUS_MGR_ID) != fc->nodeid) ? "(me)" : "");
 	if(CSRARC(fc, BUS_MGR_ID) != fc->nodeid) {
 		/* We are not the bus manager */
-		printf("\n");
 		return(0);
 	}
-	printf("(me)\n");
 
 	/* Optimize gapcount */
 	if(fc->max_hop <= MAX_GAPHOP )