Failing tests; Ice 3.1.0 on SUSE Linux 10.1

[pchapin]

Hello!

I'm just getting around to upgrading my Ice 3.0.1 installation on SUSE Linux 10.1. The compilation succeeds without any problems. Quite a few tests also pass. However, I'm seeing a failure test/Glacier2/addressFilter (details below).

I realize that SUSE Linux is not officially supported, but I've had good luck in the past getting problems fixed by posting here (thanks for the great support!) so I thought I would try it again. :-)

My system has up-to-date patches and is running in a virtual machine. I have the default firewall disabled and I have AppArmor disabled. I'm running the tests as an ordinary user (not root) in case that matters.

*** running tests in ./test/Glacier2/addressFilter
testing category filter... ok
testing adapter id filter... ./bin/glacier2router: warning: dispatch exception: Network.cpp:669: Ice::ConnectionRefusedException:
connection refused: Connection refused
identity: helloF1
facet:
operation: ice_ping
helloF1 @ "an adapter with spaces"
Outgoing.cpp:424: Ice::UnknownLocalException:
unknown local excesh: line 1: 19240 Aborted ./test/Glacier2/addressFilter/client --Ice.NullHandleAbort=1 --Ice.PrintProcessId=1 --Ice.Config=./test/Glacier2/addressFilter/attack.cfg 2>&1
ption:
Network.cpp:669: Ice::ConnectionRefusedException:
connection refused: Connection refused
failed!
Client.cpp:126: assertion `"Unexpected local exception" == 0' failed
sh: line 1: 19223 Killed ./bin/glacier2router --Ice.PrintProcessId --Ice.PrintAdapterReady --Ice.NullHandleAbort=1 --Ice.ServerIdleTime=600 --Ice.ThreadPool.Server.Size=2 --Ice.ThreadPool.Server.SizeMax=10 --Glacier2.RoutingTable.MaxSize=10 --Ice.Config=./test/Glacier2/addressFilter/router.cfg --Glacier2.Client.Endpoints="default -p 12347 -t 10000" --Glacier2.Admin.Endpoints="tcp -h 127.0.0.1 -p 12348 -t 10000" --Glacier2.CryptPasswords="./test/Glacier2/addressFilter/passwords" 2>&1
sh: line 1: 19233 Killed ./test/Glacier2/addressFilter/server --Ice.Config=./test/Glacier2/addressFilter/server.cfg --Ice.PrintProcessId --Ice.PrintAdapterReady --Ice.NullHandleAbort=1 --Ice.ServerIdleTime=600 --Ice.ThreadPool.Server.Size=2 --Ice.ThreadPool.Server.SizeMax=10 --Glacier2.RoutingTable.MaxSize=10 2>&1
test in ./test/Glacier2/addressFilter failed with exit status 256
pchapin@dustdevil:/usr/local/src/Ice-3.1.0>


Peter

[beagles]

The Glacier2 addressFilter tests are very sensitive to network configuration. The test attempts to 'discover' network details such as the host's IP address, host name and fully qualified domain names. It uses this information to test the new address filtering capabilities of Glacier2. It is very possible that this test is getting confused by your VM's network configuration.

To help us determine if this is indeed what is happening, can you pass along the information in the router.cfg, attack.cfg and server.cfg files in the test/Glacier2/addressFilter directory?

[pchapin]

Originally Posted by beagles

It is very possible that this test is getting confused by your VM's network configuration.

That sounds possible. The virtual machine has two network adapters. One has a statically assigned IP address of 192.168.1.2 with netmask 255.255.255.0. This interface connects to the host machine via a network that is entirely internal in the host. The other interface receives its address via DHCP from an internal DHCP server and gets the address 192.168.131.66 with netmask 255.255.255.0. This interface communicates with the outside world through a NAT component.

Here are the contents of the three files you mentioned.

attach.cfg:

Reject.Proxy.0=foo/helloA:tcp -h 127.0.0.1 -p 12010
Reject.Proxy.1="a cat with spaces/helloB":tcp -h 127.0.0.1 -p 12010
Reject.Proxy.2=nocat/helloC:tcp -h 127.0.0.1 -p 12010
Reject.Proxy.3=cat/helloD:tcp -h 127.0.0.1 -p 12010
Reject.Proxy.4=helloE @ bar
Accept.Proxy.0=helloF1 @ "an adapter with spaces"
Accept.Proxy.1=helloF @ foo


router.cfg:

Ice.Default.Locator=locator:tcp -h dustdevil -p 12010
Glacier2.Client.Trace.Reject=0
#
Glacier2.Filter.Address.Reject=*
Glacier2.Filter.AdapterId.Accept=foo "an adapter with spaces"


server.cfg:

BackendAdapter.Endpoints=tcp -p 12010 -t 20000


Peter

[beagles]

Originally Posted by pchapin

Ice.Default.Locator=locator:tcp -h dustdevil -p 12010

The hostname "dustdevil" seems a likely culprit here because its a test on an indirect proxy that is causing the problem. It's sounds like Ice is trying to use this hostname but can't resolve an IP address from it. I recommend checking your VM's network configuration to determine whether 'dustdevil' can be used to establish TCP/IP network connections.

Cheers

[pchapin]

Originally Posted by beagles

The hostname "dustdevil" seems a likely culprit here because its a test on an indirect proxy that is causing the problem. It's sounds like Ice is trying to use this hostname but can't resolve an IP address from it.

I tried doing a "ping dustdevil" command from inside the virtual machine. The command was successful and the address 127.0.0.2 was returned for the name "dustdevil." This name to IP mapping has been set up in /etc/hosts.

I'm less convinced that the problem is related to my virtual machine. I also compiled Ice v3.1.0 on another SUSE 10.1 box that is running on real hardware. This box does have the local firewall running. As before the compilation was successful but the tests fail in exactly the same place. The three *.cfg files you asked about earlier are the same on the second system as they are on the first with the exception that the name "morning" (also unqualified) is used in place of "dustdevil." The name morning resolves locally on that system to 127.0.0.2 as I described for dustdevil.

So to summarize I have two SUSE 10.1 systems, one in a virtual machine and one not that are configured similarly and for which the addressFilter tests are failing in exactly the same way.

Peter

[beagles]

Right. I didn't mean to imply that it was a problem specific to running Ice under a VM. Knowing that it the test fails to function as expected in a non-VM environment is informative, however.

The best way to diagnose this problem is to turn on network tracing (see this FAQ) to determine what connections are being used and attempted. Can you try this and forward the output?

Cheers

[pchapin]

Originally Posted by beagles

The best way to diagnose this problem is to turn on network tracing (see this FAQ) to determine what connections are being used and attempted. Can you try this and forward the output?

Sorry about the long delay in getting back to you on this. A lot has been going on around here... been distracted.

Anyway... I did the trace you suggested on the failing test. The results are below. I redirected the output to a file and the information in the file is not precisely in the same order as it appears interactively (I assume due to buffering issues). Basically all the trace messages appear before any of the other ones.

It looks like the system is listening to 127.0.0.1 but trying to connect to 127.0.0.2. It's probably trying to connect to the 127.0.0.2 address because that's the address associated with the name "dustdevil" in /etc/hosts. Here is a copy of my /etc/hosts for reference:

---> begin /etc/hosts <---

127.0.0.1 localhost

# special IPv6 addresses
::1 localhost ipv6-localhost ipv6-loopback

fe00::0 ipv6-localnet

ff00::0 ipv6-mcastprefix
ff02::1 ipv6-allnodes
ff02::2 ipv6-allrouters
ff02::3 ipv6-allhosts
127.0.0.2 dustdevil.ecet.vtc.edu dustdevil
192.168.1.2 dustdevil.ecet.vtc.edu dustdevil
192.168.1.1 whirlwind

This was generated by SUSE Linux's setup program except that I added the last line.

Peter

---> Begin trace dump <---

testing category filter... ok
testing adapter id filter..[ ../../../bin/glacier2router: Network: accepting tcp connections at 127.0.0.1:12347 ]
[ ../../../bin/glacier2router: Network: attempting to bind to tcp socket 192.168.131.66:12347 ]
[ ../../../bin/glacier2router: Network: accepting tcp connections at 192.168.131.66:12347 ]
[ ../../../bin/glacier2router: Network: attempting to bind to tcp socket 192.168.1.2:12347 ]
[ ../../../bin/glacier2router: Network: accepting tcp connections at 192.168.1.2:12347 ]
[ ../../../bin/glacier2router: Network: attempting to bind to tcp socket 127.0.0.1:12348 ]
[ ../../../bin/glacier2router: Network: accepting tcp connections at 127.0.0.1:12348 ]
[ ../../../bin/glacier2router: Network: attempting to bind to tcp socket 127.0.0.1:0 ]
[ ../../../bin/glacier2router: Network: accepting tcp connections at 127.0.0.1:4616 ]
. helloF1 @ "an adapter with spaces"
Outgoing.cpp:424: Ice::UnknownLocalException:
unknown local exception:
Network.cpp:669: Ice::ConnectionRefusedException:
connection refused: Connection refused
failed!
Client.cpp:126: assertion `"Unexpected local exception" == 0' failed
[ ../../../bin/glacier2router: Network: accepted tcp connection
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1190 ]
[ ../../../bin/glacier2router: Network: shutting down tcp connection for reading and writing
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1190 ]
[ ../../../bin/glacier2router: Network: closing tcp connection
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1190 ]
[ ../../../bin/glacier2router: Network: accepted tcp connection
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4003 ]
[ ../../../bin/glacier2router: Network: shutting down tcp connection for reading and writing
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4003 ]
[ ../../../bin/glacier2router: Network: closing tcp connection
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4003 ]
[ ../../../bin/glacier2router: Network: accepted tcp connection
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4004 ]
[ ../../../bin/glacier2router: Network: shutting down tcp connection for reading and writing
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4004 ]
[ ../../../bin/glacier2router: Network: closing tcp connection
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4004 ]
[ ../../../bin/glacier2router: Network: accepted tcp connection
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4005 ]
[ ../../../bin/glacier2router: Network: shutting down tcp connection for reading and writing
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4005 ]
[ ../../../bin/glacier2router: Network: closing tcp connection
local address = 192.168.131.66:12347
remote address = 192.168.131.66:4005 ]
[ ../../../bin/glacier2router: Network: accepted tcp connection
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1194 ]
[ ../../../bin/glacier2router: Network: shutting down tcp connection for reading and writing
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1194 ]
[ ../../../bin/glacier2router: Network: closing tcp connection
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1194 ]
[ ../../../bin/glacier2router: Network: accepted tcp connection
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1195 ]
[ ../../../bin/glacier2router: Network: trying to establish tcp connection to 127.0.0.2:12010 ]
[ ../../../bin/glacier2router: Network: trying to establish tcp connection to 127.0.0.2:12010 ]
[ ../../../bin/glacier2router: Network: trying to establish tcp connection to 127.0.0.2:12010 ]
[ ../../../bin/glacier2router: Network: trying to establish tcp connection to 127.0.0.2:12010 ]
../../../bin/glacier2router: warning: dispatch exception: Network.cpp:669: Ice::ConnectionRefusedException:
connection refused: Connection refused
identity: helloF1
facet:
operation: ice_ping
[ ../../../bin/glacier2router: Network: shutting down tcp connection for reading and writing
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1195 ]
[ ../../../bin/glacier2router: Network: closing tcp connection
local address = 192.168.1.2:12347
remote address = 192.168.1.2:1195 ]

[beagles]

Thanks for getting back to us with that info!

I'm inclined to think that the test is failing simply because of a bug in how the addressFilter script configures the test drivers. I don't have SUSE here so I have to ask some pretty mundane questions

- Where does the 127.0.0.2 address come from? e.g firewall software, second local loopback?
- Is the interface available when you run the tests?

Cheers

[pchapin]

Originally Posted by beagles

- Where does the 127.0.0.2 address come from? e.g firewall software, second local loopback?
- Is the interface available when you run the tests?

The 127.0.0.2 address is associated with the name "dustdevil" (no domain part) in /etc/hosts. It's a loopback address so, if I understand properly, there is no specific interface involved. For example I can ping anything in 127.x.y.z and there is an immediate response.

I did a little experimentation, however. I happen to have a trivial TCP server on hand that outputs the date and time when one connects to it. (Basically it's the first program in Steven's book, "Unix Network Programming"). When the server binds to INADDR_ANY I can telnet to it like so

telnet 127.0.0.1 9000 (works)
telnet 127.0.0.2 9000 (works)
telnet dustdevil 9000 (works)

Here 9000 is the port the server is listening on.

Next I modified the program to explicitly bind to 127.0.0.1. Then I get the following

telnet 127.0.0.1 9000 (works)
telnet 127.0.0.2 9000 (connection refused)
telnet dustdevil 9000 (connection refused)

The last case is almost certainly what's happening with the Ice tests. The server must be explicitly binding to 127.0.0.1 but the client is connecting to "dustdevil" and that's resolving to 127.0.0.2. So I think you are right: there is probably a bug in the test fixture. It seems to be using an address to define one end of the connection and a name to define the other. There is an assumption being made that an unqualified name must correspond to the exact address 127.0.0.1 and that assumption is incorrect in this case.

Thanks for your attention on this case. If by working with this I can help make Ice even just slightly better, that would please me. :-)