Bug 193043 - Connect of iscsi target does not create /dev/ad node
Summary: Connect of iscsi target does not create /dev/ad node
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 10.0-RELEASE
Hardware: Any Any
: Normal Affects Only Me
Assignee: Edward Tomasz Napierala
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-08-26 19:50 UTC by JJ Day
Modified: 2014-11-19 10:35 UTC (History)
2 users (show)

See Also:
trasz: mfc-stable10+


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description JJ Day 2014-08-26 19:50:50 UTC
I am installing FreeBSD v10.0 (r268785) on a new machine and need to use iSCSI for some external storage. The NAS target is currently serving Windows and Mac volumes. This is the first target for FreeBSD (and the first time I have used iSCSI on FreeBSD). Everything seems correct and FreeBSD connects to the target at boot, the target supplies one LUN, but I do not get a /dev/da* node created.

iscsi.conf:
#
#  test storage via iscsi
#
t0 {
   TargetAddress = 10.31.251.18
   targetname = iqn.2014-08.int.trng:Master.iscsi1.vg0.teststore
   authmethod = CHAP
   chapIName  = testroot
   chapsecret = ************
     }


iscsictl -Lv
Session ID:       10
Initiator name:   iqn.1994-09.org.freebsd:test08.trng.int
Initiator portal: 
Initiator alias:  
Target name:      iqn.2014-08.int.trng:Master.iscsi1.vg0.teststore
Target portal:    10.31.251.18
Target alias:     
User:             testroot
Secret:           ************
Mutual user:      
Mutual secret:    
Session type:     Normal
Session state:    Connected
Failure reason:   
Header digest:    None
Data digest:      None
DataSegmentLen:   262144
ImmediateData:    Yes
iSER (RDMA):      No
Device nodes:     


NAS target report:
initiator:iqn.1994-09.org.freebsd:test08.trng.int
ip:10.31.251.103
state:active
Comment 1 Edward Tomasz Napierala freebsd_committer 2014-09-09 14:37:12 UTC
Can you do "camcontrol devlist -v" and paste the output?  Also, could you include dmesg output?
Comment 2 JJ Day 2014-09-10 17:55:32 UTC
 

camcontrol:
scbus0 on ata0 bus 0:
<>                                 at scbus0 target -1 lun -1 ()
scbus1 on ata2 bus 0:
<OCZ SOLID SSD 02.10104>           at scbus1 target 0 lun 0 (pass0,ada0)
<>                                 at scbus1 target -1 lun -1 ()
scbus2 on ata3 bus 0:
<>                                 at scbus2 target -1 lun -1 ()
scbus3 on iscsi0 bus 0:
<NAS iSCSI-VDISK 0>                at scbus3 target 0 lun 2 (da0,pass1)
<>                                 at scbus3 target 0 lun -1 ()
scbus-1 on xpt0 bus 0:
<>                                 at scbus-1 target -1 lun -1 (xpt0)
 
 
dmesg:
Copyright (c) 1992-2014 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
      The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 10.0-RELEASE-p7 #0 r268785: Wed Jul 16 23:56:44 CDT 2014
    root@testsys:/usr/obj/usr/src/sys/HOST2 i386
FreeBSD clang version 3.3 (tags/RELEASE_33/final 183502) 20130610
CPU: Pentium(R) Dual-Core  CPU      E5200  @ 2.50GHz (2502.29-MHz 686-class CPU)
  Origin = "GenuineIntel"  Id = 0x10676  Family = 0x6  Model = 0x17  Stepping = 6
  Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
  Features2=0xe39d<SSE3,DTES64,MON,DS_CPL,EST,TM2,SSSE3,CX16,xTPR,PDCM>
  AMD Features=0x20100000<NX,LM>
  AMD Features2=0x1<LAHF>
  TSC: P-state invariant, performance statistics
real memory  = 4294967296 (4096 MB)
avail memory = 3407663104 (3249 MB)
Event timer "LAPIC" quality 400
ACPI APIC Table: <Shuttl Shuttle >
FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
FreeBSD/SMP: 1 package(s) x 2 core(s)
 cpu0 (BSP): APIC ID:  0
 cpu1 (AP): APIC ID:  1
ioapic0: Changing APIC ID to 4
ioapic0 <Version 2.0> irqs 0-23 on motherboard
kbd1 at kbdmux0
random: <Software, Yarrow> initialized
acpi0: <Shuttl Shuttle> on motherboard
acpi0: Power Button (fixed)
acpi0: reservation of 0, a0000 (3) failed
acpi0: reservation of 100000, cf490000 (3) failed
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
attimer0: <AT timer> port 0x40-0x43 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff irq 0,8 on acpi0
device_attach: hpet0 attach returned 12
atrtc0: <AT realtime clock> port 0x70-0x73 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
acpi_button0: <Power Button> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
vgapci0: <VGA-compatible display> port 0xff00-0xff07 mem 0xfdf00000-0xfdf7ffff,0xd0000000-0xdfffffff,0xfd500000-0xfd5fffff irq 16 at device 2.0 on pci0
agp0: <Intel G33 SVGA controller> on vgapci0
agp0: aperture size is 256M, detected 7164k stolen memory
vgapci0: Boot video device
vgapci1: <VGA-compatible display> mem 0xfde80000-0xfdefffff at device 2.1 on pci0
pci0: <multimedia, HDA> at device 27.0 (no driver attached)
pcib1: <ACPI PCI-PCI bridge> at device 28.0 on pci0
pci1: <ACPI PCI bus> on pcib1
pcib2: <ACPI PCI-PCI bridge> at device 28.1 on pci0
pci2: <ACPI PCI bus> on pcib2
pci2: <network, ethernet> at device 0.0 (no driver attached)
pcib3: <ACPI PCI-PCI bridge> at device 28.2 on pci0
pci3: <ACPI PCI bus> on pcib3
pcib4: <ACPI PCI-PCI bridge> at device 28.3 on pci0
pci4: <ACPI PCI bus> on pcib4
uhci0: <Intel 82801G (ICH7) USB controller USB-A> port 0xfe00-0xfe1f irq 23 at device 29.0 on pci0
usbus0 on uhci0
uhci1: <Intel 82801G (ICH7) USB controller USB-B> port 0xfd00-0xfd1f irq 19 at device 29.1 on pci0
usbus1 on uhci1
uhci2: <Intel 82801G (ICH7) USB controller USB-C> port 0xfc00-0xfc1f irq 18 at device 29.2 on pci0
usbus2 on uhci2
uhci3: <Intel 82801G (ICH7) USB controller USB-D> port 0xfb00-0xfb1f irq 16 at device 29.3 on pci0
usbus3 on uhci3
ehci0: <Intel 82801GB/R (ICH7) USB 2.0 controller> mem 0xfdfff000-0xfdfff3ff irq 23 at device 29.7 on pci0
usbus4: EHCI version 1.0
usbus4 on ehci0
pcib5: <ACPI PCI-PCI bridge> at device 30.0 on pci0
pci5: <ACPI PCI bus> on pcib5
em0: <Intel(R) PRO/1000 Legacy Network Connection 1.0.6> port 0xcf00-0xcf3f mem 0xfd4a0000-0xfd4bffff,0xfd440000-0xfd47ffff irq 17 at device 9.0 on pci5
em0: Ethernet address: 00:07:e9:a5:60:ca
em1: <Intel(R) PRO/1000 Legacy Network Connection 1.0.6> port 0xce00-0xce3f mem 0xfd4c0000-0xfd4dffff irq 18 at device 9.1 on pci5
em1: Ethernet address: 00:07:e9:a5:60:cb
pci5: <serial bus, FireWire> at device 10.0 (no driver attached)
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <Intel ICH7 UDMA100 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xfa00-0xfa0f at device 31.1 on pci0
ata0: <ATA channel> at channel 0 on atapci0
atapci1: <Intel ICH7 SATA300 controller> port 0xf900-0xf907,0xf800-0xf803,0xf700-0xf707,0xf600-0xf603,0xf500-0xf50f irq 19 at device 31.2 on pci0
ata2: <ATA channel> at channel 0 on atapci1
ata3: <ATA channel> at channel 1 on atapci1
pci0: <serial bus, SMBus> at device 31.3 (no driver attached)
acpi_tz0: <Thermal Zone> on acpi0
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: model IntelliMouse Explorer, device ID 4
pmtimer0 on isa0
orm0: <ISA Option ROM> at iomem 0xef000-0xeffff pnpid ORM0000 on isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
est0: <Enhanced SpeedStep Frequency Control> on cpu0
p4tcc0: <CPU Frequency Thermal Control> on cpu0
est1: <Enhanced SpeedStep Frequency Control> on cpu1
p4tcc1: <CPU Frequency Thermal Control> on cpu1
Timecounters tick every 1.000 msec
IP Filter: v5.1.2 initialized.  Default = block all, Logging = enabled
random: unblocking device.
usbus0: 12Mbps Full Speed USB v1.0
usbus1: 12Mbps Full Speed USB v1.0
usbus2: 12Mbps Full Speed USB v1.0
usbus3: 12Mbps Full Speed USB v1.0
usbus4: 480Mbps High Speed USB v2.0
acpi_tz0: _TMP value is absurd, ignored (-73.0C)
ugen0.1: <Intel> at usbus0
uhub0: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
ugen3.1: <Intel> at usbus3
uhub1: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus3
ugen2.1: <Intel> at usbus2
uhub2: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus2
ugen1.1: <Intel> at usbus1
uhub3: <Intel UHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus1
ugen4.1: <Intel> at usbus4
uhub4: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus4
uhub0: 2 ports with 2 removable, self powered
uhub1: 2 ports with 2 removable, self powered
uhub2: 2 ports with 2 removable, self powered
uhub3: 2 ports with 2 removable, self powered
ada0 at ata2 bus 0 scbus1 target 0 lun 0
ada0: <OCZ SOLID SSD 02.10104> ATA-8 SATA 2.x device
ada0: Serial Number MK04090314CAC000D
ada0: 150.000MB/s transfers (SATA, UDMA5, PIO 512bytes)
ada0: 61136MB (125206528 512 byte sectors: 16H 63S/T 16383C)
ada0: Previously was known as ad4
SMP: AP CPU #1 Launched!
Timecounter "TSC-low" frequency 1251144100 Hz quality 1000
Root mount waiting for: usbus4
Root mount waiting for: usbus4
uhub4: 8 ports with 8 removable, self powered
Root mount waiting for: usbus4
Trying to mount root from ufs:/dev/ada0p2 [rw]...
ugen2.2: <vendor 0x1a86> at usbus2
uchcom0: <vendor 0x1a86 USB2.0-Ser, rev 1.10/2.54, addr 2> on usbus2
uchcom0: CH341 detected
iscsi: version 2.3.1
<following lines added after boot by iscontrol>
0] ic_init: cam subsystem initialized
da0 at iscsi0 bus 0 scbus3 target 0 lun 2
da0: <NAS iSCSI-VDISK 0> Fixed Direct Access SCSI-4 device
da0: Serial Number    
da0: 95232MB (195035136 512 byte sectors: 255H 63S/T 12140C)
 
Iscontrol:
iscontrol[1327]: running
iscontrol[1327]: (pass1:iscsi0:0:0:2):  tagged openings now 0
Comment 3 Edward Tomasz Napierala freebsd_committer 2014-09-10 19:09:51 UTC
From dmesg and camcontrol, it looks like /dev/da0 should be there.  However, it also looks like you're using the old initiator now (iscontrol), and not the new one (iscsictl).  So, can you try with the _new_ initiator and paste the camcontrol and dmesg again?  Thanks!
Comment 4 JJ Day 2014-09-10 23:32:47 UTC
Sorry - yes that was the old initiator and /dev/da0 was present.

this is with the new initiator. 
dmeag output is identical to the line
uchcom0: CH341 detected

the lines starting at
iscsi: version 2.3.1 
and after were added by the old initiator. There is no additional dmesg output using iscsid and the new initiator.


Camcontrol post iscsictl:
scbus0 on ata0 bus 0:
<>                                 at scbus0 target -1 lun -1 ()
scbus1 on ata2 bus 0:
<OCZ SOLID SSD 02.10104>           at scbus1 target 0 lun 0 (pass0,ada0)
<>                                 at scbus1 target -1 lun -1 ()
scbus2 on ata3 bus 0:
<>                                 at scbus2 target -1 lun -1 ()
scbus3 on iscsi1 bus 0:
<>                                 at scbus3 target -1 lun -1 ()
scbus-1 on xpt0 bus 0:
<>                                 at scbus-1 target -1 lun -1 (xpt0)
Comment 5 Edward Tomasz Napierala freebsd_committer 2014-09-11 13:32:16 UTC
What serves as the iSCSI target?  Also, could you run the following commands, as root (they basically enable all kinds of initiator debug):

sysctl kern.icl.debug=10
sysctl kern.iscsi.debug=10
pkill -KILL iscsid
iscsid -l 10

Then remove the iSCSI session using iscsictl, add it again, and paste log contents?
Comment 6 JJ Day 2014-09-11 17:31:50 UTC
The target is a Thecus NAS.


This is the debug.log after the above 4 commands and running iscsictl:
Sep 11 11:01:47 test08 iscsid[1352]: waiting for request from the kernel
Sep 11 11:06:47 test08 iscsid[1352]: incoming connection; forking child process #0
Sep 11 11:06:47 test08 iscsid[1352]: waiting for request from the kernel
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): connecting to 10.31.251.18
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): setting session timeout to 60 seconds
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): Capsicum capability mode enabled
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): beginning Login phase; sending Login PDU
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "AuthMethod=None,CHAP"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "InitiatorName=iqn.1994-09.org.freebsd:test08.tng.int"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "SessionType=Normal"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "TargetName=iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "TargetPortalGroupTag=1"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "AuthMethod=CHAP"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): beginning CHAP authentication; sending CHAP_A
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "CHAP_A=5"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): waiting for CHAP_A/CHAP_C/CHAP_I
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): sending CHAP_N/CHAP_R
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "CHAP_A=5"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "CHAP_I=78"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "CHAP_C=0xa95f0e4f0a6641e72ebc410e2e45a5558b752d86ca0944ebdb8c32643f60d0e8bfde37ca4578b17334f281633726b8c39b"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "CHAP_N=testroot"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "CHAP_R=0xfe8238ad4e07cc0dc7450d2f7ec3c136"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): waiting for CHAP result
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): CHAP authentication done
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): beginning parameter negotiation
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "HeaderDigest=None"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "DataDigest=None"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "ImmediateData=Yes"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "MaxBurstLength=131072"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "FirstBurstLength=131072"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "InitialR2T=Yes"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "MaxRecvDataSegmentLength=131072"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "DefaultTime2Wait=0"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "DefaultTime2Retain=0"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "ErrorRecoveryLevel=0"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key to send: "MaxOutstandingR2T=1"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "HeaderDigest=None"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "DataDigest=None"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "ImmediateData=Yes"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "MaxBurstLength=131072"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "FirstBurstLength=65536"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "InitialR2T=Yes"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "DefaultTime2Wait=2"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "DefaultTime2Retain=0"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "ErrorRecoveryLevel=0"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "MaxOutstandingR2T=1"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): key received: "MaxRecvDataSegmentLength=262144"
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): target prefers not to do header digest; we'll comply
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): target prefers not to do data digest; we'll comply
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): parameter negotiation done; transitioning to Full Feature phase
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): handing off connection to the kernel
Sep 11 11:06:47 test08 iscsid[1379]: 10.31.251.18 (iqn.2014-08.int.tng:Master.iscsi1.vg0.teststore): nothing more to do; exiting
Comment 7 Edward Tomasz Napierala freebsd_committer 2014-09-16 11:53:55 UTC
Did the problem happen with 10.0-RELEASE?  Alternatively, could you test the patch below:

Index: sys/dev/iscsi/iscsi.c
===================================================================
--- sys/dev/iscsi/iscsi.c       (revision 271570)
+++ sys/dev/iscsi/iscsi.c       (working copy)
@@ -2179,7 +2179,7 @@ iscsi_action(struct cam_sim *sim, union ccb *ccb)
                cpi->hba_misc = PIM_EXTLUNS;
                cpi->hba_eng_cnt = 0;
                cpi->max_target = 0;
-               cpi->max_lun = 0;
+               cpi->max_lun = 255;
                cpi->initiator_id = ~0;
                strlcpy(cpi->sim_vid, "FreeBSD", SIM_IDLEN);
                strlcpy(cpi->hba_vid, "iSCSI", HBA_IDLEN);
Comment 8 JJ Day 2014-09-16 19:07:51 UTC
I don't know if the problem started with 10.0-RELEASE. I had not tried it prior to my install of 10.0-RELEASE-p7 r268785.

I had already done an svn update to revision 271684. Do I need to revert to 271570?

The information in /usr/src/sys/dev/iscsi/iscsi.c is:
 * $FreeBSD: releng/10.0/sys/dev/iscsi/iscsi.c 259336 2013-12-13 21:41:23Z trasz $

and the code section is:
		cpi->target_sprt = 0;
		//cpi->hba_misc = PIM_NOBUSRESET;
		cpi->hba_misc = 0;
		cpi->hba_eng_cnt = 0;
		cpi->max_target = 0;
		cpi->max_lun = 255;
		//cpi->initiator_id = 0; /* XXX */
		cpi->initiator_id = 64; /* XXX */
		strlcpy(cpi->sim_vid, "FreeBSD", SIM_IDLEN);

Do I have an old file?
I have not yet tried to apply the patch.
Comment 9 Edward Tomasz Napierala freebsd_committer 2014-09-17 08:20:21 UTC
Ah, sorry.  This looked very similar to other bug I tracked down yesterday, but that one was caused by commit that was never merged to 10-STABLE, so this problem here is different.

Ok, forget the patch.  Could you catch a packet trace of connection initiation, eg. by using Wireshark?  That should explain what is going on.
Comment 10 JJ Day 2014-09-17 13:55:03 UTC
I have never used Wireshark so will need to load it, read the man pages and figure out how to use it. Can you tell me what the capture parameters should be?
Comment 11 JJ Day 2014-09-19 00:45:17 UTC
Sorry it took so long. This is the decode display of the tshark capture. If you need the raw capture file please let me know. The last three lines continue to repeat until the capture is terminated.


  1 0.000000000 00:14:fd:11:fd:81 -> Broadcast    ARP 60 Who has 10.31.251.16?  Tell 10.31.251.18
  2 1.000202000 00:14:fd:11:fd:81 -> Broadcast    ARP 60 Who has 10.31.251.16?  Tell 10.31.251.18
  3 2.000398000 00:14:fd:11:fd:81 -> Broadcast    ARP 60 Who has 10.31.251.16?  Tell 10.31.251.18
  4 3.996811000 00:14:fd:11:fd:81 -> Broadcast    ARP 60 Who has 10.31.251.16?  Tell 10.31.251.18
  5 4.997015000 00:14:fd:11:fd:81 -> Broadcast    ARP 60 Who has 10.31.251.16?  Tell 10.31.251.18
  6 5.997134000 00:14:fd:11:fd:81 -> Broadcast    ARP 60 Who has 10.31.251.16?  Tell 10.31.251.18
  7 27.551762000  10.31.251.3 -> 10.31.251.18 TCP 74 12469→3260 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 WS=64 SACK_PERM=1 TSval=431738 TSecr=0
  8 27.552046000 10.31.251.18 -> 10.31.251.3  TCP 74 3260→12469 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 SACK_PERM=1 TSval=2007010786 TSecr=431738 WS=32
  9 27.552373000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=1 Ack=1 Win=66560 Len=0 TSval=431739 TSecr=2007010786
 10 27.556556000  10.31.251.3 -> 10.31.251.18 iSCSI 274 Login Command
 11 27.556798000 10.31.251.18 -> 10.31.251.3  TCP 66 3260→12469 [ACK] Seq=1 Ack=209 Win=5792 Len=0 TSval=2007010787 TSecr=431743
 12 27.556952000 10.31.251.18 -> 10.31.251.3  iSCSI 154 Login Response (Success)
 13 27.557462000  10.31.251.3 -> 10.31.251.18 iSCSI 126 Login Command
 14 27.557675000 10.31.251.18 -> 10.31.251.3  iSCSI 210 Login Response (Success)
 15 27.558451000  10.31.251.3 -> 10.31.251.18 iSCSI 174 Login Command
 16 27.558663000 10.31.251.18 -> 10.31.251.3  iSCSI 114 Login Response (Success)
 17 27.559540000  10.31.251.3 -> 10.31.251.18 iSCSI 342 Login Command
 18 27.559787000 10.31.251.18 -> 10.31.251.3  iSCSI 342 Login Response (Success)
 19 27.565285000  10.31.251.3 -> 10.31.251.18 iSCSI 114 SCSI: Inquiry LUN: 0x00 
 20 27.565549000 10.31.251.18 -> 10.31.251.3  iSCSI 150 SCSI: Data In LUN: 0x00 (Inquiry Response Data) [SCSI transfer limited due to allocation_length too small]
 21 27.669235000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=701 Ack=641 Win=1048960 Len=0 TSval=431856 TSecr=2007010789
 22 29.576958000  10.31.251.3 -> 10.31.251.18 TCP 114 12469→3260 [PSH, ACK] Seq=701 Ack=641 Win=1048960 Len=48 TSval=433764 TSecr=2007010789
 23 29.577217000 10.31.251.18 -> 10.31.251.3  iSCSI 114 NOP In
 24 29.682358000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=749 Ack=689 Win=1048960 Len=0 TSval=433869 TSecr=2007011292
 25 31.649203000  10.31.251.3 -> 10.31.251.18 TCP 114 12469→3260 [PSH, ACK] Seq=749 Ack=689 Win=1048960 Len=48 TSval=435836 TSecr=2007011292
 26 31.649466000 10.31.251.18 -> 10.31.251.3  iSCSI 114 NOP In
 27 31.755344000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=797 Ack=737 Win=1048960 Len=0 TSval=435942 TSecr=2007011810
 28 33.708197000  10.31.251.3 -> 10.31.251.18 TCP 114 12469→3260 [PSH, ACK] Seq=797 Ack=737 Win=1048960 Len=48 TSval=437895 TSecr=2007011810
 29 33.708464000 10.31.251.18 -> 10.31.251.3  iSCSI 114 NOP In
 30 33.810067000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=845 Ack=785 Win=1048960 Len=0 TSval=437997 TSecr=2007012325
 31 35.721033000  10.31.251.3 -> 10.31.251.18 TCP 114 12469→3260 [PSH, ACK] Seq=845 Ack=785 Win=1048960 Len=48 TSval=439908 TSecr=2007012325
 32 35.721241000 10.31.251.18 -> 10.31.251.3  iSCSI 114 NOP In
 33 35.821171000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=893 Ack=833 Win=1048960 Len=0 TSval=440008 TSecr=2007012828
 34 37.755201000  10.31.251.3 -> 10.31.251.18 TCP 114 12469→3260 [PSH, ACK] Seq=893 Ack=833 Win=1048960 Len=48 TSval=441942 TSecr=2007012828
 35 37.755482000 10.31.251.18 -> 10.31.251.3  iSCSI 114 NOP In
 36 37.857097000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=941 Ack=881 Win=1048960 Len=0 TSval=442044 TSecr=2007013336
 37 39.798214000  10.31.251.3 -> 10.31.251.18 TCP 114 12469→3260 [PSH, ACK] Seq=941 Ack=881 Win=1048960 Len=48 TSval=443985 TSecr=2007013336
 38 39.798380000 10.31.251.18 -> 10.31.251.3  iSCSI 114 NOP In
 39 39.904348000  10.31.251.3 -> 10.31.251.18 TCP 66 12469→3260 [ACK] Seq=989 Ack=929 Win=1048960 Len=0 TSval=444091 TSecr=2007013847
 40 41.817701000  10.31.251.3 -> 10.31.251.18 TCP 114 12469→3260 [PSH, ACK] Seq=989 Ack=929 Win=1048960 Len=48 TSval=446004 TSecr=2007013847
 41 41.817934000 10.31.251.18 -> 10.31.251.3  iSCSI 114 NOP In
Comment 12 Edward Tomasz Napierala freebsd_committer 2014-09-26 10:06:55 UTC
Hm.  There are at least two weird things here: the fact that there is no REPORT_LUNS, and that the responses to iSCSI pings (NOP-In) PDUs are not decoded.  Could you send me the raw capture?  Thanks!
Comment 13 JJ Day 2014-09-26 17:20:41 UTC
I am on the road and will return tomorrow. I will upload the raw capture file then.
Meanwhile, to the best of my memory, I did the capture with:
#tshark -i em0 -p -w capture.file
and the dump with:
#tshark -r capture.file > capture.print

Was there some other parameter needed to get the rest of the needed data?
Comment 14 JJ Day 2014-09-29 04:47:30 UTC
Here is the link to the raw file:  http://www.filedropper.com/tshark
Comment 15 Edward Tomasz Napierala freebsd_committer 2014-10-04 12:10:13 UTC
Thank you.  Turns out it's a bug, fixed in 11-CURRENT as r272409.  Unfortunately the fix won't be a part of 10.1-RELEASE.  The bug only affects iSCSI targets that claim compliance with an ancient SCSI version (SPC-2) and do not have LUN 0 configured.  Easiest way to work around it would be to set up LUN 0 instead of 2.
Comment 16 JJ Day 2014-10-05 14:58:22 UTC
The NAS default LUN assignment is on a lowest available basis when the target is created. Reassigning them so LUN zero is used for the FreeBSD target solves the problem since only one target is required.

Thank you.
Comment 17 Edward Tomasz Napierala freebsd_committer 2014-11-19 10:35:13 UTC
The fix was MFC-d to 10-STABLE as r273976.