On Oct 9, 2009, at 6:14 PM, C Linus Hicks linush@verizon.net wrote:

On Fri, 2009-10-09 at 17:53 -0400, Ross Walker wrote:

...

On Fri, Oct 9, 2009 at 5:37 PM, C Linus Hicks linush@verizon.net wrote:

...

I am trying to install Oracle RAC in a two node cluster for testing purposes, so performance is not something that concerns me. I just want to go through the process all the way to creating a database. I have all the prerequisites except the shared storage and thought I'd give this a try.

I'm running:

• CentOS 5.3 kernel 2.6.18-164.el5
• iscsitarget-1.4.18-1
• iscsi-initiator-utils-6.2.0.868-0.18.el5_3.1

I can discover and login to the node using iscsiadm on the server that is not also running iet, and see the new scsi disk.

When I try to login using iscsiadm on the server that is running the ietd daemon, I see packets going over the lo interface in both directions, but I get error 8 - connection timed out. Wireshark is reporting TCP Previous segment lost errors with large sequence numbers like 2999833 and 8999718.

Has anybody tried this, and can anybody offer any help?

You can only do that if you use blockio for your targets, otherwise fileio will cause a deadlock on the page cache between the target's usage of it and the initiator's usage of it.

So for iet, that means /etc/iet/ietd.conf should define the Lun like this:

Lun 0 Path=/dev/sdb,Type=blockio,ScsiId=asmdg,ScsiSN=dg0

If that's all it takes to make it do blockio instead of fileio, then that is already the case. Deadlocks on the cache pages - wouldn't that only affect I/O and not logging in?

Ok, well at least that's covered.

Is iptables disabled?

Also the latest version of IET won't advertise the loopback on discovery unless you are discovering on that same same loopback address. You can still statically connect though, which I recommend for loopback connections.

-Ross

On Oct 10, 2009, at 12:29 AM, C Linus Hicks linush@verizon.net wrote:

On Fri, 2009-10-09 at 21:42 -0400, Ross Walker wrote:

...

On Oct 9, 2009, at 6:14 PM, C Linus Hicks wrote:

...

So for iet, that means /etc/iet/ietd.conf should define the Lun like this:

Lun 0 Path=/dev/sdb,Type=blockio,ScsiId=asmdg,ScsiSN=dg0

If that's all it takes to make it do blockio instead of fileio, then that is already the case. Deadlocks on the cache pages - wouldn't that only affect I/O and not logging in?

Ok, well at least that's covered.

Is iptables disabled?

Also the latest version of IET won't advertise the loopback on discovery unless you are discovering on that same same loopback address. You can still statically connect though, which I recommend for loopback connections.

Yep, iptables doesn't run on that machine, the service is disabled. And I'm just using the one IP address on that machine.

Here's my /var/lib/iscsi/ifaces/iface0 file:

iface.transport_name = tcp iface.hwaddress = 00:1D:92:B4:50:6E

Is the transport_name for loopback still tcp? The discovery appears to work properly:

[root@lh6 iscsi]# iscsiadm -m discovery -t st -p 10.200.1.6:3260 -I iface0 -P 1 Target: iqn.2009-10.net.linush:storage.disk1.sys1.asmdg Portal: 10.200.1.6:3260,1 Iface Name: iface0

I found a way to make the entry in /var/lib/iscsi/static which is just a symbolic link back to the entry in /var/lib/iscsi/nodes, but you must be seeing different documentation because I don't see any thing that talks about logging in using the static entry. At any rate, I run this command and get the output as shown:

[root@lh6 iscsi]# iscsiadm -m node -T iqn. 2009-10.net.linush:storage.disk1.sys1.asmdg -p 10.200.1.6:3260 -l Logging in to [iface: iface0, target: iqn. 2009-10.net.linush:storage.disk1.sys1.asmdg, portal: 10.200.1.6,3260] iscsiadm: Could not login to [iface: iface0, target: iqn. 2009-10.net.linush:storage.disk1.sys1.asmdg, portal: 10.200.1.6,3260]: iscsiadm: initiator reported error (8 - connection timed out)

And here's the node:

[root@lh6 iscsi]# cat nodes/iqn.2009-10.net.linush :storage.disk1.sys1.asmdg/10.200.1.6,3260,1/iface0 # BEGIN RECORD 2.0-868 node.name = iqn.2009-10.net.linush:storage.disk1.sys1.asmdg node.tpgt = 1 node.startup = manual iface.hwaddress = 00:1D:92:B4:50:6E iface.iscsi_ifacename = iface0 iface.net_ifacename = default iface.transport_name = tcp node.discovery_port = 0 node.discovery_type = static node.session.initial_cmdsn = 0 node.session.initial_login_retry_max = 4 node.session.cmds_max = 128 node.session.queue_depth = 32 node.session.auth.authmethod = None node.session.timeo.replacement_timeout = 120 node.session.err_timeo.abort_timeout = 15 node.session.err_timeo.lu_reset_timeout = 30 node.session.err_timeo.host_reset_timeout = 60 node.session.iscsi.FastAbort = Yes node.session.iscsi.InitialR2T = No node.session.iscsi.ImmediateData = Yes node.session.iscsi.FirstBurstLength = 262144 node.session.iscsi.MaxBurstLength = 16776192 node.session.iscsi.DefaultTime2Retain = 0 node.session.iscsi.DefaultTime2Wait = 2 node.session.iscsi.MaxConnections = 1 node.session.iscsi.MaxOutstandingR2T = 1 node.session.iscsi.ERL = 0 node.conn[0].address = 10.200.1.6 node.conn[0].port = 3260 node.conn[0].startup = manual node.conn[0].tcp.window_size = 524288 node.conn[0].tcp.type_of_service = 0 node.conn[0].timeo.logout_timeout = 15 node.conn[0].timeo.login_timeout = 15 node.conn[0].timeo.auth_timeout = 45 node.conn[0].timeo.noop_out_interval = 5 node.conn[0].timeo.noop_out_timeout = 5 node.conn[0].iscsi.MaxRecvDataSegmentLength = 131072 node.conn[0].iscsi.HeaderDigest = None,CRC32C node.conn[0].iscsi.IFMarker = No node.conn[0].iscsi.OFMarker = No # END RECORD

...

From ifconfig:

eth2 Link encap:Ethernet HWaddr 00:1D:92:B4:50:6E inet addr:10.200.1.6 Bcast:10.200.1.255 Mask:255.255.255.0

What does the ietd.conf, initiators.allow and targets.allow look like?

What is your network setup? Are you using a vif on the loopback?

-Ross

On Sun, 2009-10-11 at 15:13 -0400, C Linus Hicks wrote:

There's no VIF on loopback. The machine running iet has two NICs, the private interconnect should not be playing a role. It's IP address is 10.200.2.2/24 while the local subnet is 10.200.1.0/24 and the iet machine is IP address 10.200.1.6.

From running strace on the iscsid daemon, it appears to be taking what

looks to me like an unexpected error. In the text below, look for the first series of "poll" system calls. Just after that section is where I initiate the iscsiadm login command. Then about 100 lines later on, it issues a connect call that returns "-1 EINPROGRESS (Operation now in progress)". Then it goes back to polling, this time on two sockets including the one it just tried to connect on. In a little while it probably reaches the retry limit and closes that socket. It makes another connect attempt that fails with the same error. There are a total of five connect attempts, but I have cut out some of the repeated text.

strace output: ---------------------------------------------------------------------- execve("/sbin/iscsid", ["iscsid", "-f", "-c", "/etc/iscsi/iscsid.conf"], [/* 29 vars */]) = 0 brk(0) = 0x28de000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dc000 uname({sys="Linux", node="lh6.linush.net", ...}) = 0 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) open("/etc/ld.so.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=161740, ...}) = 0 mmap(NULL, 161740, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2ac7443dd000 close(3) = 0 open("/lib64/libc.so.6", O_RDONLY) = 3 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p\332\341_2\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=1713096, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac744405000 mmap(0x325fe00000, 3494168, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x325fe00000 mprotect(0x325ff4c000, 2097152, PROT_NONE) = 0 mmap(0x326014c000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14c000) = 0x326014c000 mmap(0x3260151000, 16664, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3260151000 close(3) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac744406000 arch_prctl(ARCH_SET_FS, 0x2ac744406250) = 0 mprotect(0x326014c000, 16384, PROT_READ) = 0 mprotect(0x325f01b000, 4096, PROT_READ) = 0 munmap(0x2ac7443dd000, 161740) = 0 rt_sigaction(SIGINT, {0x41ec00, [], SA_RESTORER, 0x325fe30280}, {SIG_DFL, [], 0}, 8) = 0 rt_sigaction(SIGPIPE, {0x41ec00, [], SA_RESTORER, 0x325fe30280}, {SIG_DFL, [], 0}, 8) = 0 rt_sigaction(SIGTERM, {0x41ec00, [], SA_RESTORER, 0x325fe30280}, {SIG_DFL, [], 0}, 8) = 0 brk(0) = 0x28de000 brk(0x28ff000) = 0x28ff000 open("/sys/module/scsi_transport_iscsi/version", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(3, "2.0-871\n", 4096) = 8 close(3) = 0 munmap(0x2ac7443dd000, 4096) = 0 write(2, "iscsid: ", 8iscsid: ) = 8 write(2, "transport class version 2.0-871."..., 55transport class version 2.0-871. iscsid version 2.0-868) = 55 write(2, "\n", 1 ) = 1 umask(0177) = 022 socket(PF_FILE, SOCK_STREAM, 0) = 3 bind(3, {sa_family=AF_FILE, path=@"ISCSIADM_ABSTRACT_NAMESPACE"}, 110) = 0 listen(3, 32) = 0 socket(PF_NETLINK, SOCK_RAW, 8) = 4 getpid() = 28308 bind(4, {sa_family=AF_NETLINK, pid=28308, groups=00000001}, 12) = 0 open("/etc/iscsi/initiatorname.iscsi", O_RDONLY) = 5 fstat(5, {st_mode=S_IFREG|0644, st_size=50, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(5, "InitiatorName=iqn.2009-10.net.li"..., 4096) = 50 read(5, "", 4096) = 0 close(5) = 0 munmap(0x2ac7443dd000, 4096) = 0 open("/etc/iscsi/initiatorname.iscsi", O_RDONLY) = 5 fstat(5, {st_mode=S_IFREG|0644, st_size=50, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(5, "InitiatorName=iqn.2009-10.net.li"..., 4096) = 50 read(5, "", 4096) = 0 close(5) = 0 munmap(0x2ac7443dd000, 4096) = 0 uname({sys="Linux", node="lh6.linush.net", ...}) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x2ac7444062e0) = 28309 getpriority(PRIO_PROCESS, 0) = 20 setpriority(PRIO_PROCESS, 0, 4294967286) = 0 getpriority(PRIO_PROCESS, 0) = 30 open("/proc/28308/oom_adj", O_WRONLY) = 5 write(5, "-16", 3) = 3 write(5, "-17", 3) = 3 close(5) = 0 mlockall(MCL_CURRENT|MCL_FUTURE) = 0 getrlimit(RLIMIT_NOFILE, {rlim_cur=4*1024, rlim_max=64*1024}) = 0 setrlimit(RLIMIT_NOFILE, {rlim_cur=16*1024, rlim_max=64*1024}) = 0 open("/etc/iscsi/iscsid.conf", O_RDONLY) = 5 fstat(5, {st_mode=S_IFREG|0600, st_size=7338, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(5, "#\n# Open-iSCSI default configura"..., 4096) = 4096 read(5, "that is also\n# a power of 2. The"..., 4096) = 3242 read(5, "", 4096) = 0 close(5) = 0 munmap(0x2ac7443dd000, 4096) = 0 poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = -1 EINTR (Interrupted system call) --- SIGCHLD (Child exited) @ 0 (0) --- wait4(0, NULL, WNOHANG, NULL) = 28309 poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 1 ([{fd=3, revents=POLLIN}]) accept(3, 0, NULL) = 5 getsockopt(5, SOL_SOCKET, SO_PEERCRED, "\227n\0\0\0\0\0\0\0\0\0\0", [12]) = 0 socket(PF_FILE, SOCK_STREAM, 0) = 6 fcntl(6, F_GETFL) = 0x2 (flags O_RDWR) fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(6, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) close(6) = 0 socket(PF_FILE, SOCK_STREAM, 0) = 6 fcntl(6, F_GETFL) = 0x2 (flags O_RDWR) fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(6, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) close(6) = 0 open("/etc/nsswitch.conf", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0644, st_size=1696, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(6, "#\n# /etc/nsswitch.conf\n#\n# An ex"..., 4096) = 1696 read(6, "", 4096) = 0 close(6) = 0 munmap(0x2ac7443dd000, 4096) = 0 open("/etc/ld.so.cache", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0644, st_size=161740, ...}) = 0 mmap(NULL, 161740, PROT_READ, MAP_PRIVATE, 6, 0) = 0x2ac7443dd000 close(6) = 0 open("/lib64/libnss_files.so.2", O_RDONLY) = 6 read(6, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\37\0\0\0\0\0\0"..., 832) = 832 fstat(6, {st_mode=S_IFREG|0755, st_size=53880, ...}) = 0 mmap(NULL, 2139432, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 6, 0) = 0x2ac744407000 mprotect(0x2ac744411000, 2093056, PROT_NONE) = 0 mmap(0x2ac744610000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 6, 0x9000) = 0x2ac744610000 close(6) = 0 mprotect(0x2ac744610000, 4096, PROT_READ) = 0 munmap(0x2ac7443dd000, 161740) = 0 open("/etc/passwd", O_RDONLY) = 6 fcntl(6, F_GETFD) = 0 fcntl(6, F_SETFD, FD_CLOEXEC) = 0 fstat(6, {st_mode=S_IFREG|0644, st_size=1963, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(6, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1963 close(6) = 0 munmap(0x2ac7443dd000, 4096) = 0 read(5, "\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\375g\10\377\177\0\0\20\375g\10\377\177\0\0"..., 5272) = 5272 open("/sys/class/iscsi_session", O_RDONLY|O_NONBLOCK|O_DIRECTORY) = 6 fstat(6, {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0 fcntl(6, F_SETFD, FD_CLOEXEC) = 0 getdents(6, /* 2 entries */, 4096) = 48 getdents(6, /* 0 entries */, 4096) = 0 close(6) = 0 open("/sys/class/iscsi_transport", O_RDONLY|O_NONBLOCK|O_DIRECTORY) = 6 fstat(6, {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0 fcntl(6, F_SETFD, FD_CLOEXEC) = 0 getdents(6, /* 4 entries */, 4096) = 96 getdents(6, /* 0 entries */, 4096) = 0 close(6) = 0 open("/sys/class/iscsi_transport/iser/handle", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(6, "18446744071717264032\n", 4096) = 21 close(6) = 0 munmap(0x2ac7443dd000, 4096) = 0 open("/sys/class/iscsi_transport/iser/caps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(6, "0x9\n", 4096) = 4 close(6) = 0 munmap(0x2ac7443dd000, 4096) = 0 open("/sys/class/iscsi_transport/tcp/handle", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(6, "18446744071712301184\n", 4096) = 21 close(6) = 0 munmap(0x2ac7443dd000, 4096) = 0 open("/sys/class/iscsi_transport/tcp/caps", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(6, "0x39\n", 4096) = 5 close(6) = 0 munmap(0x2ac7443dd000, 4096) = 0 brk(0x2920000) = 0x2920000 brk(0x2942000) = 0x2942000 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 6 socket(PF_NETLINK, SOCK_RAW, 0) = 7 bind(7, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(7, {sa_family=AF_NETLINK, pid=28308, groups=00000000}, [137438953484]) = 0 sendto(7, "\24\0\0\0\22\0\1\3\365\201\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\370\0\0\0\20\0\2\0\365\201\321J\224n\0\0\0\0\4\3\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 1004 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\365\201\321J\224n\0\0\0\0\0\0\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 sendto(7, "\24\0\0\0\26\0\1\3\366\201\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"<\0\0\0\24\0\2\0\366\201\321J\224n\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 196 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\366\201\321J\224n\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 192 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\366\201\321J\224n\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 close(7) = 0 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 7 ioctl(7, SIOCGIFHWADDR, {ifr_name="lo", ifr_hwaddr=00:00:00:00:00:00}) = 0 ioctl(7, SIOCGIFHWADDR, {ifr_name="eth2", ifr_hwaddr=00:1d:92:b4:50:6e}) = 0 close(7) = 0 setsockopt(6, SOL_SOCKET, SO_BINDTODEVICE, "eth2\0", 5) = 0 setsockopt(6, SOL_TCP, TCP_NODELAY, [1], 4) = 0 setsockopt(6, SOL_SOCKET, SO_RCVBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_RCVBUF, [4296015872], [4]) = 0 setsockopt(6, SOL_SOCKET, SO_SNDBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_SNDBUF, [4296015872], [4]) = 0 fcntl(6, F_GETFL) = 0x2 (flags O_RDWR) fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(6, {sa_family=AF_INET, sin_port=htons(3260), sin_addr=inet_addr("10.200.1.6")}, 128) = -1 EINPROGRESS (Operation now in progress) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) close(6) = 0 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 6 socket(PF_NETLINK, SOCK_RAW, 0) = 7 bind(7, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(7, {sa_family=AF_NETLINK, pid=28308, groups=00000000}, [184268356289822732]) = 0 sendto(7, "\24\0\0\0\22\0\1\3\5\202\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\370\0\0\0\20\0\2\0\5\202\321J\224n\0\0\0\0\4\3\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 1004 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\5\202\321J\224n\0\0\0\0\0\0\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 sendto(7, "\24\0\0\0\26\0\1\3\6\202\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"<\0\0\0\24\0\2\0\6\202\321J\224n\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 196 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\6\202\321J\224n\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 192 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\6\202\321J\224n\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 close(7) = 0 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 7 ioctl(7, SIOCGIFHWADDR, {ifr_name="lo", ifr_hwaddr=00:00:00:00:00:00}) = 0 ioctl(7, SIOCGIFHWADDR, {ifr_name="eth2", ifr_hwaddr=00:1d:92:b4:50:6e}) = 0 close(7) = 0 setsockopt(6, SOL_SOCKET, SO_BINDTODEVICE, "eth2\0", 5) = 0 setsockopt(6, SOL_TCP, TCP_NODELAY, [1], 4) = 0 setsockopt(6, SOL_SOCKET, SO_RCVBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_RCVBUF, [4296015872], [4]) = 0 setsockopt(6, SOL_SOCKET, SO_SNDBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_SNDBUF, [4296015872], [4]) = 0 fcntl(6, F_GETFL) = 0x2 (flags O_RDWR) fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(6, {sa_family=AF_INET, sin_port=htons(3260), sin_addr=inet_addr("10.200.1.6")}, 128) = -1 EINPROGRESS (Operation now in progress) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout)

------------- Cut repeated stuff ----------------

poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout) close(6) = 0 write(5, "\1\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2464) = 2464 close(5) = 0 close(5) = -1 EBADF (Bad file descriptor) brk(0x290f000) = 0x290f000 brk(0x2908000) = 0x2908000 poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 1 ([{fd=3, revents=POLLIN}]) accept(3, 0, NULL) = 5 getsockopt(5, SOL_SOCKET, SO_PEERCRED, "\255n\0\0\0\0\0\0\0\0\0\0", [12]) = 0 open("/etc/passwd", O_RDONLY) = 6 fcntl(6, F_GETFD) = 0 fcntl(6, F_SETFD, FD_CLOEXEC) = 0 fstat(6, {st_mode=S_IFREG|0644, st_size=1963, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ac7443dd000 read(6, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1963 close(6) = 0 munmap(0x2ac7443dd000, 4096) = 0 read(5, "\v\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 5272) = 5272 write(5, "\v\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2464) = 2464 close(5) = 0 close(5) = -1 EBADF (Bad file descriptor) write(2, "iscsid: ", 8iscsid: ) = 8 write(2, "iscsid shutting down.", 21iscsid shutting down.) = 21 write(2, "\n", 1 ) = 1 close(4) = 0 close(3) = 0 exit_group(0) = ?

On Sun, 2009-10-11 at 17:51 -0400, Ross Walker wrote:

I don't know much about open-iscsi, just IET and the best way to diagnose iSCSI problems is via tcpdump and wireshark not strace.

Is the iscsi-target service running?

[root@lh6 iscsi]# netstat -nlp | grep 3260 tcp 0 0 0.0.0.0:3260 0.0.0.0:* LISTEN 16475/ietd tcp 0 0 :::3260 :::* LISTEN 16475/ietd

On Sun, 2009-10-11 at 23:26 -0400, Ross Walker wrote:

Can you send a short tcpdump between initiator and target during discovery/login?

Sure. Note that all this traffic is on the "lo" interface.

The discovery command and tcpdump output:

[root@lh6 ~]# iscsiadm -m discovery -t st -p 10.200.1.6:3260 -P 1 Target: iqn.2009-10.net.linush:storage.disk1.sys1.asmdg Portal: 10.200.1.6:3260,1 Iface Name: iface0

[root@lh6 iscsi]# tcpdump -i lo -n -vv 00:03:04.584545 IP (tos 0x0, ttl 64, id 55720, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: S, cksum 0x4851 (correct), 3727115272:3727115272(0) win 32792 <mss 16396,sackOK,timestamp 296394144 0,nop,wscale 8> 00:03:04.584547 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20331: S, cksum 0x6389 (correct), 3721615280:3721615280(0) ack 3727115273 win 32768 <mss 16396,sackOK,timestamp 296394144 296394144,nop,wscale 8> 00:03:04.584559 IP (tos 0x0, ttl 64, id 55721, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: ., cksum 0x4c2e (correct), 1:1(0) ack 1 win 129 <nop,nop,timestamp 296394144 296394144> 00:03:04.584608 IP (tos 0x0, ttl 64, id 55722, offset 0, flags [DF], proto: TCP (6), length: 100) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: P 1:49(48) ack 1 win 129 <nop,nop,timestamp 296394145 296394144> 00:03:04.584615 IP (tos 0x0, ttl 64, id 51728, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.iscsi-target > 10.200.1.6.20331: ., cksum 0x4bfd (correct), 1:1(0) ack 49 win 128 <nop,nop,timestamp 296394145 296394145> 00:03:04.584623 IP (tos 0x0, ttl 64, id 55723, offset 0, flags [DF], proto: TCP (6), length: 304) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: P 49:301(252) ack 1 win 129 <nop,nop,timestamp 296394145 296394145> 00:03:04.584626 IP (tos 0x0, ttl 64, id 51729, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.iscsi-target > 10.200.1.6.20331: ., cksum 0x4afc (correct), 1:1(0) ack 301 win 133 <nop,nop,timestamp 296394145 296394145> 00:03:04.584668 IP (tos 0x0, ttl 64, id 51730, offset 0, flags [DF], proto: TCP (6), length: 244) 10.200.1.6.iscsi-target > 10.200.1.6.20331: P 1:193(192) ack 301 win 133 <nop,nop,timestamp 296394145 296394145> 00:03:04.584684 IP (tos 0x0, ttl 64, id 55724, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: ., cksum 0x4a3c (correct), 301:301(0) ack 193 win 133 <nop,nop,timestamp 296394145 296394145> 00:03:04.584706 IP (tos 0x0, ttl 64, id 55725, offset 0, flags [DF], proto: TCP (6), length: 100) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: P 301:349(48) ack 193 win 133 <nop,nop,timestamp 296394145 296394145> 00:03:04.584714 IP (tos 0x0, ttl 64, id 55726, offset 0, flags [DF], proto: TCP (6), length: 68) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: P, cksum 0x17d2 (incorrect (-> 0x3b43), 349:365(16) ack 193 win 133 <nop,nop,timestamp 296394145 296394145> 00:03:04.584719 IP (tos 0x0, ttl 64, id 51731, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.iscsi-target > 10.200.1.6.20331: ., cksum 0x49fc (correct), 193:193(0) ack 365 win 133 <nop,nop,timestamp 296394145 296394145> 00:03:04.584908 IP (tos 0x0, ttl 64, id 51732, offset 0, flags [DF], proto: TCP (6), length: 192) 10.200.1.6.iscsi-target > 10.200.1.6.20331: P 193:333(140) ack 365 win 133 <nop,nop,timestamp 296394145 296394145> 00:03:04.586785 IP (tos 0x0, ttl 64, id 55727, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: F, cksum 0x4969 (correct), 365:365(0) ack 333 win 137 <nop,nop,timestamp 296394147 296394145> 00:03:04.586807 IP (tos 0x0, ttl 64, id 51733, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.iscsi-target > 10.200.1.6.20331: F, cksum 0x496a (correct), 333:333(0) ack 366 win 133 <nop,nop,timestamp 296394147 296394147> 00:03:04.586816 IP (tos 0x0, ttl 64, id 55728, offset 0, flags [DF], proto: TCP (6), length: 52) 10.200.1.6.20331 > 10.200.1.6.iscsi-target: ., cksum 0x4966 (correct), 366:366(0) ack 334 win 137 <nop,nop,timestamp 296394147 296394147>

16 packets captured 32 packets received by filter 0 packets dropped by kernel

------------------------------------------------------------------------------

Check the timestamps and you will see either three or six second delays between groups of three packets.

[root@lh6 ~]# iscsiadm -m node -T iqn.2009-10.net.linush:storage.disk1.sys1.asmdg -p 10.200.1.6:3260 -I iface0 -l Logging in to [iface: iface0, target: iqn.2009-10.net.linush:storage.disk1.sys1.asmdg, portal: 10.200.1.6,3260] iscsiadm: Could not login to [iface: iface0, target: iqn.2009-10.net.linush:storage.disk1.sys1.asmdg, portal: 10.200.1.6,3260]: iscsiadm: initiator reported error (8 - connection timed out)

[root@lh6 iscsi]# tcpdump -i lo -n -vv 00:01:07.521652 IP (tos 0x0, ttl 64, id 4451, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20326 > 10.200.1.6.iscsi-target: S, cksum 0x9796 (correct), 3606955323:3606955323(0) win 32792 <mss 16396,sackOK,timestamp 296277080 0,nop,wscale 8> 00:01:07.521653 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20326: S, cksum 0xe4a1 (correct), 3609851344:3609851344(0) ack 3606955324 win 32768 <mss 16396,sackOK,timestamp 296277080 296277080,nop,wscale 8> 00:01:07.521661 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20326 > 10.200.1.6.iscsi-target: R, cksum 0x9fe8 (correct), 3606955324:3606955324(0) win 0 00:01:10.521958 IP (tos 0x0, ttl 64, id 4452, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20326 > 10.200.1.6.iscsi-target: S, cksum 0x8bde (correct), 3606955323:3606955323(0) win 32792 <mss 16396,sackOK,timestamp 296280080 0,nop,wscale 8> 00:01:10.521977 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20326: S, cksum 0x0501 (correct), 3612851667:3612851667(0) ack 3606955324 win 32768 <mss 16396,sackOK,timestamp 296280080 296280080,nop,wscale 8> 00:01:10.521983 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20326 > 10.200.1.6.iscsi-target: R, cksum 0x9fe8 (correct), 3606955324:3606955324(0) win 0 00:01:16.521838 IP (tos 0x0, ttl 64, id 4453, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20326 > 10.200.1.6.iscsi-target: S, cksum 0x746e (correct), 3606955323:3606955323(0) win 32792 <mss 16396,sackOK,timestamp 296286080 0,nop,wscale 8> 00:01:16.521852 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20326: S, cksum 0x48c2 (correct), 3618851542:3618851542(0) ack 3606955324 win 32768 <mss 16396,sackOK,timestamp 296286080 296286080,nop,wscale 8> 00:01:16.521859 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20326 > 10.200.1.6.iscsi-target: R, cksum 0x9fe8 (correct), 3606955324:3606955324(0) win 0 00:01:23.334823 IP (tos 0x0, ttl 64, id 58953, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20327 > 10.200.1.6.iscsi-target: S, cksum 0x29cb (correct), 3622433876:3622433876(0) win 32792 <mss 16396,sackOK,timestamp 296292893 0,nop,wscale 8> 00:01:23.334838 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20327: S, cksum 0xc911 (correct), 3634521175:3634521175(0) ack 3622433877 win 32768 <mss 16396,sackOK,timestamp 296292893 296292893,nop,wscale 8> 00:01:23.334844 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20327 > 10.200.1.6.iscsi-target: R, cksum 0x6fe2 (correct), 3622433877:3622433877(0) win 0 00:01:26.334655 IP (tos 0x0, ttl 64, id 58954, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20327 > 10.200.1.6.iscsi-target: S, cksum 0x1e13 (correct), 3622433876:3622433876(0) win 32792 <mss 16396,sackOK,timestamp 296295893 0,nop,wscale 8> 00:01:26.334668 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20327: S, cksum 0xeb5f (correct), 3637521003:3637521003(0) ack 3622433877 win 32768 <mss 16396,sackOK,timestamp 296295893 296295893,nop,wscale 8> 00:01:26.334674 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20327 > 10.200.1.6.iscsi-target: R, cksum 0x6fe2 (correct), 3622433877:3622433877(0) win 0 00:01:32.334544 IP (tos 0x0, ttl 64, id 58955, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20327 > 10.200.1.6.iscsi-target: S, cksum 0x06a3 (correct), 3622433876:3622433876(0) win 32792 <mss 16396,sackOK,timestamp 296301893 0,nop,wscale 8> 00:01:32.334562 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20327: S, cksum 0x2f0e (correct), 3643520897:3643520897(0) ack 3622433877 win 32768 <mss 16396,sackOK,timestamp 296301893 296301893,nop,wscale 8> 00:01:32.334568 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20327 > 10.200.1.6.iscsi-target: R, cksum 0x6fe2 (correct), 3622433877:3622433877(0) win 0 00:01:38.394538 IP (tos 0x0, ttl 64, id 19618, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20328 > 10.200.1.6.iscsi-target: S, cksum 0xe197 (correct), 3645440083:3645440083(0) win 32792 <mss 16396,sackOK,timestamp 296307953 0,nop,wscale 8> 00:01:38.394553 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20328: S, cksum 0x9cf7 (correct), 3634105712:3634105712(0) ack 3645440084 win 32768 <mss 16396,sackOK,timestamp 296307953 296307953,nop,wscale 8> 00:01:38.394559 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20328 > 10.200.1.6.iscsi-target: R, cksum 0x6283 (correct), 3645440084:3645440084(0) win 0 00:01:41.394358 IP (tos 0x0, ttl 64, id 19619, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20328 > 10.200.1.6.iscsi-target: S, cksum 0xd5df (correct), 3645440083:3645440083(0) win 32792 <mss 16396,sackOK,timestamp 296310953 0,nop,wscale 8> 00:01:41.394372 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20328: S, cksum 0xbf4f (correct), 3637105530:3637105530(0) ack 3645440084 win 32768 <mss 16396,sackOK,timestamp 296310953 296310953,nop,wscale 8> 00:01:41.394378 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20328 > 10.200.1.6.iscsi-target: R, cksum 0x6283 (correct), 3645440084:3645440084(0) win 0 00:01:47.394244 IP (tos 0x0, ttl 64, id 19620, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20328 > 10.200.1.6.iscsi-target: S, cksum 0xbe6f (correct), 3645440083:3645440083(0) win 32792 <mss 16396,sackOK,timestamp 296316953 0,nop,wscale 8> 00:01:47.394262 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20328: S, cksum 0x0301 (correct), 3643105421:3643105421(0) ack 3645440084 win 32768 <mss 16396,sackOK,timestamp 296316953 296316953,nop,wscale 8> 00:01:47.394269 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20328 > 10.200.1.6.iscsi-target: R, cksum 0x6283 (correct), 3645440084:3645440084(0) win 0 00:01:53.454247 IP (tos 0x0, ttl 64, id 28155, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20329 > 10.200.1.6.iscsi-target: S, cksum 0xbbdb (correct), 3661949502:3661949502(0) win 32792 <mss 16396,sackOK,timestamp 296323013 0,nop,wscale 8> 00:01:53.454261 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20329: S, cksum 0xc398 (correct), 3661464733:3661464733(0) ack 3661949503 win 32768 <mss 16396,sackOK,timestamp 296323013 296323013,nop,wscale 8> 00:01:53.454268 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20329 > 10.200.1.6.iscsi-target: R, cksum 0x779b (correct), 3661949503:3661949503(0) win 0 00:01:56.454072 IP (tos 0x0, ttl 64, id 28156, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20329 > 10.200.1.6.iscsi-target: S, cksum 0xb023 (correct), 3661949502:3661949502(0) win 32792 <mss 16396,sackOK,timestamp 296326013 0,nop,wscale 8> 00:01:56.454087 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20329: S, cksum 0xe5ea (correct), 3664464557:3664464557(0) ack 3661949503 win 32768 <mss 16396,sackOK,timestamp 296326013 296326013,nop,wscale 8> 00:01:56.454093 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20329 > 10.200.1.6.iscsi-target: R, cksum 0x779b (correct), 3661949503:3661949503(0) win 0 00:02:02.453964 IP (tos 0x0, ttl 64, id 28157, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20329 > 10.200.1.6.iscsi-target: S, cksum 0x98b3 (correct), 3661949502:3661949502(0) win 32792 <mss 16396,sackOK,timestamp 296332013 0,nop,wscale 8> 00:02:02.453982 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20329: S, cksum 0x2998 (correct), 3670464452:3670464452(0) ack 3661949503 win 32768 <mss 16396,sackOK,timestamp 296332013 296332013,nop,wscale 8> 00:02:02.453989 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20329 > 10.200.1.6.iscsi-target: R, cksum 0x779b (correct), 3661949503:3661949503(0) win 0 00:02:08.513957 IP (tos 0x0, ttl 64, id 33753, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20330 > 10.200.1.6.iscsi-target: S, cksum 0x2948 (correct), 3674292544:3674292544(0) win 32792 <mss 16396,sackOK,timestamp 296338073 0,nop,wscale 8> 00:02:08.513971 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20330: S, cksum 0x276b (correct), 3674690201:3674690201(0) ack 3674292545 win 32768 <mss 16396,sackOK,timestamp 296338073 296338073,nop,wscale 8> 00:02:08.513977 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20330 > 10.200.1.6.iscsi-target: R, cksum 0x1fdc (correct), 3674292545:3674292545(0) win 0 00:02:11.513788 IP (tos 0x0, ttl 64, id 33754, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20330 > 10.200.1.6.iscsi-target: S, cksum 0x1d90 (correct), 3674292544:3674292544(0) win 32792 <mss 16396,sackOK,timestamp 296341073 0,nop,wscale 8> 00:02:11.513803 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20330: S, cksum 0x49b6 (correct), 3677690032:3677690032(0) ack 3674292545 win 32768 <mss 16396,sackOK,timestamp 296341073 296341073,nop,wscale 8> 00:02:11.513809 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20330 > 10.200.1.6.iscsi-target: R, cksum 0x1fdc (correct), 3674292545:3674292545(0) win 0 00:02:17.513675 IP (tos 0x0, ttl 64, id 33755, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.20330 > 10.200.1.6.iscsi-target: S, cksum 0x0620 (correct), 3674292544:3674292544(0) win 32792 <mss 16396,sackOK,timestamp 296347073 0,nop,wscale 8> 00:02:17.513695 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 60) 10.200.1.6.iscsi-target > 10.200.1.6.20330: S, cksum 0x8d66 (correct), 3683689924:3683689924(0) ack 3674292545 win 32768 <mss 16396,sackOK,timestamp 296347073 296347073,nop,wscale 8> 00:02:17.513702 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: TCP (6), length: 40) 10.200.1.6.20330 > 10.200.1.6.iscsi-target: R, cksum 0x1fdc (correct), 3674292545:3674292545(0) win 0

45 packets captured 90 packets received by filter 0 packets dropped by kernel

On Sun, 2009-10-11 at 17:14 -0400, C Linus Hicks wrote:

strace output:

----- Cut a bunch of lines ----

socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 6 socket(PF_NETLINK, SOCK_RAW, 0) = 7 bind(7, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(7, {sa_family=AF_NETLINK, pid=28308, groups=00000000}, [137438953484]) = 0 sendto(7, "\24\0\0\0\22\0\1\3\365\201\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\370\0\0\0\20\0\2\0\365\201\321J\224n\0\0\0\0\4\3\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 1004 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\365\201\321J\224n\0\0\0\0\0\0\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 sendto(7, "\24\0\0\0\26\0\1\3\366\201\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"<\0\0\0\24\0\2\0\366\201\321J\224n\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 196 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\366\201\321J\224n\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 192 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\366\201\321J\224n\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 close(7) = 0 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 7 ioctl(7, SIOCGIFHWADDR, {ifr_name="lo", ifr_hwaddr=00:00:00:00:00:00}) = 0 ioctl(7, SIOCGIFHWADDR, {ifr_name="eth2", ifr_hwaddr=00:1d:92:b4:50:6e}) = 0 close(7) = 0 setsockopt(6, SOL_SOCKET, SO_BINDTODEVICE, "eth2\0", 5) = 0 setsockopt(6, SOL_TCP, TCP_NODELAY, [1], 4) = 0 setsockopt(6, SOL_SOCKET, SO_RCVBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_RCVBUF, [4296015872], [4]) = 0 setsockopt(6, SOL_SOCKET, SO_SNDBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_SNDBUF, [4296015872], [4]) = 0 fcntl(6, F_GETFL) = 0x2 (flags O_RDWR) fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(6, {sa_family=AF_INET, sin_port=htons(3260), sin_addr=inet_addr("10.200.1.6")}, 128) = -1 EINPROGRESS (Operation now in progress) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout)

--------- Cut a bunch more lines --------

I believe the problem is evident from the strace. He binds the socket to eth2 based on querying the MAC address. That means he will only receive packets on eth2 and since the network layer has determined that origin and destination are the same, it's passing the traffic across the loopback interface. Thus he will never see a response from the ietd daemon.

If my interpretation is correct, then the two possibilities I see are that this is either a design restriction or a bug.

On Sun, 2009-10-11 at 17:14 -0400, C Linus Hicks wrote:

strace output:

--- a bunch of lines cut ---

socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 6 socket(PF_NETLINK, SOCK_RAW, 0) = 7 bind(7, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(7, {sa_family=AF_NETLINK, pid=28308, groups=00000000}, [137438953484]) = 0 sendto(7, "\24\0\0\0\22\0\1\3\365\201\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\370\0\0\0\20\0\2\0\365\201\321J\224n\0\0\0\0\4\3\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 1004 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\365\201\321J\224n\0\0\0\0\0\0\1\0\0\0I\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 sendto(7, "\24\0\0\0\26\0\1\3\366\201\321J\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"<\0\0\0\24\0\2\0\366\201\321J\224n\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 196 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\366\201\321J\224n\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 192 recvmsg(7, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\366\201\321J\224n\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 close(7) = 0 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 7 ioctl(7, SIOCGIFHWADDR, {ifr_name="lo", ifr_hwaddr=00:00:00:00:00:00}) = 0 ioctl(7, SIOCGIFHWADDR, {ifr_name="eth2", ifr_hwaddr=00:1d:92:b4:50:6e}) = 0 close(7) = 0 setsockopt(6, SOL_SOCKET, SO_BINDTODEVICE, "eth2\0", 5) = 0 setsockopt(6, SOL_TCP, TCP_NODELAY, [1], 4) = 0 setsockopt(6, SOL_SOCKET, SO_RCVBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_RCVBUF, [4296015872], [4]) = 0 setsockopt(6, SOL_SOCKET, SO_SNDBUF, [524288], 4) = 0 getsockopt(6, SOL_SOCKET, SO_SNDBUF, [4296015872], [4]) = 0 fcntl(6, F_GETFL) = 0x2 (flags O_RDWR) fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(6, {sa_family=AF_INET, sin_port=htons(3260), sin_addr=inet_addr("10.200.1.6")}, 128) = -1 EINPROGRESS (Operation now in progress) poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=0, events=0}], 3, 250) = 0 (Timeout) poll([{fd=6, events=POLLOUT}], 1, 1) = 0 (Timeout)

--- a bunch more lines cut ---

So by looking in the code, it will avoid binding to the device under "default" conditions. I removed the MAC address from the iface0 file and the login works.

On Sun, 2009-10-11 at 17:43 -0400, Ross Walker wrote:

I'm a little confused now, you are running IET and open-iscsi on the same host, buy using an external interface for the connection between the two instead of the loopback? You would get much better throughput on the loopback.

Sure, that makes sense. Given that /var/lib/iscsi/ifaces/iface0 seems to require a MAC address, I did not think there was a way to do that. Perhaps you could enlighten me...