[Vortex] BUG: Endless warnings if connection is refused

Jens Alfke jens at mooseyard.com
Fri Mar 21 20:23:32 CET 2008


I'm seeing some odd behavior, which I think happened after I updated  
to the latest SVN revision (3338) last week. When I open a connection,  
if the connection's refused (i.e. no one at the destination listening  
on that port), Vortex starts logging a constant series of warnings.

The first warning is:

CRITICAL: vortex-frame-factory: unable to read a line, error was:  
Connection refused

And then the following five warnings appear in a loop, over and over:

CRITICAL: vortex-frame-factory: an error have ocurred while reading  
socket
vortex-greetings: no frame received from remote peer
vortex-connection: found NULL frame referecence connection=2, checking  
to wait for read operation..
vortex-io: received a non valid socket (-1), unable to add to the set
vortex-connection: failed to add session to the waiting socket
...

This goes on at high speed until, in my case, the connection timeout  
expires. If the client code didn't set a timeout, I think Vortex might  
get stuck forever in this loop.

Below is a transcript showing all Vortex logging up to the point of  
the first warning, with a backtrace at the point of the warning. It  
shows that the "connection refused" socket error is being detected by  
__vortex_frame_readline. This could be a problem introduced by making  
the connect() nonblocking — the connection has failed, but Vortex  
seems to think it succeeded, is interpreting the error as a  
recoverable problem reading data, and is retrying.

—Jens

12:04:48.785| Vortex: vortex-connection: invoking connection_new  
threaded mode
12:04:48.785| Vortex: vortex-thread: finished vortex_cond_wait from / 
Hack/Others/Vortex/vortex/src/MacOSX/../../src/vortex_thread.c:886
12:04:48.785| Vortex: vortex-profiles: profile http://mooseyard.com/cloudy/uri/challenge 
  is not registered, storing settings
12:04:48.785| Vortex: vortex-thread-pool: --> thread from pool  
processing new job
12:04:48.785| Vortex: vortex-connection: executing connection new in  
thread mode to 66.92.48.212:42539 id=2
12:04:48.785| Vortex: vortex-connection: actual flags state before  
setting nonblocking: 2
12:04:48.785| Vortex: vortex-connection: actual flags state after  
setting nonblocking: 6
12:04:48.785| Vortex: vortex-connection: setting connection as non- 
blocking
12:04:48.785| Vortex: vortex-connection: actual flags state before  
setting nonblocking: 6
12:04:48.785| Vortex: vortex-connection: actual flags state after  
setting nonblocking: 6
12:04:48.785| Vortex: vortex-connection: setting connection as non- 
blocking
12:04:48.785| Vortex: vortex-connection: detected connect timeout  
during 10 seconds (starting from: 1206126288)
12:04:48.830| Vortex: vortex-connection: __vortex_connection_wait_on  
(id=2, sock=13) operation finished, err=1, errno=36 (Operation now in  
progress) (ellapsed: 0)
12:04:48.830| Vortex: vortex-connection: timeout operation finished,  
with err=1, errno=36, ellapsed time=0 (seconds)
12:04:48.830| Vortex: vortex-connection: connection adding channel #0
12:04:48.830| Vortex: vortex-connection: getting initial greetings  
frame..
12:04:48.830| WARNING*** : CRITICAL: Vortex+vortex-frame-factory:  
unable to read a line, error was: Connection refused
[Switching to process 1015 thread 0x5e03]
[Switching to process 1015 thread 0x5e03]
(gdb) bt
#0  Warn (msg=0x71474) at /Hack/Cloudy/../MYUtilities/Logging.m:164
#1  0x00028ee2 in beepLogCallback (log_level=2, domain=0x1a3463  
"vortex-frame-factory", message=0xe229010 "unable to read a line,  
error was: Connection refused") at /Hack/Cloudy/Source/Network/ 
PersonConnection.m:54
#2  0x0002a980 in vortexLogCallback (domain=0x1a3463 "vortex-frame- 
factory", log_level=VORTEX_LEVEL_CRITICAL, message=0x1a35b0 "unable to  
read a line, error was: %s", args=0xb02ddd0c "\336\244\314\222PJ) 
\016\0306\032") at /Hack/Cloudy/Source/Network/BEEP/BPEndpoint.m:70
#3  0x0015ddd2 in _vortex_log_common (domain=0x1a3463 "vortex-frame- 
factory", log_level=VORTEX_LEVEL_CRITICAL, message=0x1a35b0 "unable to  
read a line, error was: %s", args=0xb02ddd0c "\336\244\314\222PJ) 
\016\0306\032") at /Hack/Others/Vortex/vortex/src/MacOSX/../../src/ 
vortex.c:604
#4  0x0015e080 in _vortex_log (domain=0x1a3463 "vortex-frame-factory",  
log_level=VORTEX_LEVEL_CRITICAL, message=0x1a35b0 "unable to read a  
line, error was: %s") at /Hack/Others/Vortex/vortex/src/MacOSX/../../ 
src/vortex.c:695
#5  0x0017224c in __vortex_frame_readline (connection=0xe294e00,  
buffer=0xb02ddd9c "", maxlen=99) at /Hack/Others/Vortex/vortex/src/ 
MacOSX/../../src/vortex_frame_factory.c:744
#6  0x0017281c in vortex_frame_get_next (connection=0xe294e00) at / 
Hack/Others/Vortex/vortex/src/MacOSX/../../src/vortex_frame_factory.c: 
913
#7  0x00175155 in vortex_greetings_process (connection=0xe294e00) at / 
Hack/Others/Vortex/vortex/src/MacOSX/../../src/vortex_greetings.c:250
#8  0x00175491 in vortex_greetings_client_process  
(connection=0xe294e00) at /Hack/Others/Vortex/vortex/src/MacOSX/../../ 
src/vortex_greetings.c:383
#9  0x0016bee7 in __vortex_connection_new (data=0xe28d0a0) at /Hack/ 
Others/Vortex/vortex/src/MacOSX/../../src/vortex_connection.c:1445
#10 0x00180603 in __vortex_thread_pool_dispatcher (data=0x3c6d20) at / 
Hack/Others/Vortex/vortex/src/MacOSX/../../src/vortex_thread_pool.c:99
#11 0x92bccc55 in _pthread_start ()
#12 0x92bccb12 in thread_start ()

-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 1875 bytes
Desc: not available
Url : http://lists.aspl.es/pipermail/vortex/attachments/20080321/f0155bd8/attachment.bin 


More information about the Vortex mailing list