I've been using the multi interface and lately I've noticed that it does
not always callback to inform me of additional sockets that need to be
monitored. Below are two traces. It is somewhat odd in that I find the
behavior mostly when I strace the process. I'm not sure what that has to
do with it.

In the good case, notice that the first attempt times out on socket #9, and
then socket #10 is allocated and the client code informed about it. The
request succeeds.

In the second case, the failure case, the first attempt times out on socket
#9, but socket #10 is created (i've seen in the strace output) the request
is sent (seen via tcpdump), but socket #10 is never announced to the
client. Eventually the entire request fails.

Any ideas? I've looked into the multi code, but I have not been able to
figure out the problem yet. I will continue looking.

Thanks,
Jason

chronos_at_localhost:/tmp sudo strace -o /tmp/flimflam.strace
/usr/sbin/flimflamd --debug=portal -n

flimflamd[13289]: src/portal.c:portal_service_state_changed() eth0:
Checking http://clients3.google.com/generate_204 on ethernet_687f74408236
flimflamd[13289]: src/portal.c:portal_service_state_changed() eth0: Using
name servers 172.16.255.1,172.24.220.65,172.25.126.65
flimflamd[13289]: src/portal.c:portal_service_state_changed() curl
flimflamd[13289]: src/portal.c:timer_callback() set timeout 1 ms (expires
34346.173061734)
flimflamd[13289]: src/portal.c:debug_function() curl: 0x78d2f0c4 is at send
pipe head!
flimflamd[13289]: src/portal.c:debug_function() curl: STATE: CONNECT =>
WAITRESOLVE handle 0x78d40924; (connection #0)
flimflamd[13289]: src/portal.c:socket_callback() FD#9 action=1
flimflamd[13289]: src/portal.c:socket_callback() FD#9 set (using slot 0)
flimflamd[13289]: src/portal.c:socket_callback() FD#9 action=4
flimflamd[13289]: src/portal.c:socket_callback() FD#9 unset (using slot 0)
flimflamd[13289]: src/portal.c:debug_function() curl: About to connect() to
clients3.google.com port 80 (#0)
flimflamd[13289]: src/portal.c:debug_function() curl: Trying
2001:4860:4003:802::1006...
flimflamd[13289]: src/portal.c:debug_function() curl: Local Interface eth0
is ip fe80::6a7f:74ff:fe40:8236 using address family 10
flimflamd[13289]: src/portal.c:debug_function() curl: bind failed with
errno 99: Cannot assign requested address
flimflamd[13289]: src/portal.c:debug_function() curl: Trying
74.125.226.238...
flimflamd[13289]: src/portal.c:debug_function() curl: Local Interface eth0
is ip 172.31.194.38 using address family 2
flimflamd[13289]: src/portal.c:debug_function() curl: Local port: 0
flimflamd[13289]: src/portal.c:debug_function() curl: STATE: WAITRESOLVE =>
WAITCONNECT handle 0x78d40924; (connection #0)
flimflamd[13289]: src/portal.c:socket_callback() FD#9 action=2
flimflamd[13289]: src/portal.c:socket_callback() FD#9 set (using slot 0)
flimflamd[13289]: src/portal.c:timer_callback() set timeout 586 ms (expires
34346.766507011)
flimflamd[13289]: No previous default gateway, use 172.31.195.254
flimflamd[13289]: Set default route for eth0: gw 172.31.195.254 metric 0
flimflamd[13289]: eth0 {add} address 172.31.194.38/16 (af 2) label eth0
flimflamd[13289]: eth0 {del} address 172.31.194.38/16 (af 2) label eth0
flimflamd[13289]: eth0 {add} address 172.31.194.38/23 (af 2) label eth0
flimflamd[13289]: eth0 {add} route 0.0.0.0 gw 172.31.195.254 scope 0
<UNIVERSE>
flimflamd[13289]: src/portal.c:source_check_expiration() request has
timeout'ed
flimflamd[13289]: src/portal.c:source_check_expiration() request has
timeout'ed
flimflamd[13289]: src/portal.c:debug_function() curl: After 588ms connect
time, move on!
flimflamd[13289]: src/portal.c:debug_function() curl: Trying
74.125.226.239...
flimflamd[13289]: src/portal.c:debug_function() curl: Local Interface eth0
is ip 172.31.194.38 using address family 2
flimflamd[13289]: src/portal.c:debug_function() curl: Local port: 0
flimflamd[13289]: src/portal.c:timer_callback() set timeout 588 ms (expires
34347.357322111)
flimflamd[13289]: src/portal.c:source_dispatch() mcode = 0, remaining = 1
flimflamd[13289]: src/portal.c:socket_callback() FD#10 action=2
flimflamd[13289]: src/portal.c:socket_callback() FD#10 set (using slot 1)
flimflamd[13289]: src/portal.c:socket_callback() FD#9 action=4
flimflamd[13289]: src/portal.c:socket_callback() FD#9 unset (using slot 0)
flimflamd[13289]: src/portal.c:source_dispatch() mcode = 0, remaining = 1
flimflamd[13289]: src/portal.c:debug_function() curl: Connected to
clients3.google.com (74.125.226.239) port 80 (#0)
flimflamd[13289]: src/portal.c:debug_function() curl: STATE: WAITCONNECT =>
DO handle 0x78d40924; (connection #0)
flimflamd[13289]: src/portal.c:debug_function() curl: STATE: DO => DO_DONE
handle 0x78d40924; (connection #0)
flimflamd[13289]: src/portal.c:debug_function() curl: STATE: DO_DONE =>
WAITPERFORM handle 0x78d40924; (connection #0)
flimflamd[13289]: src/portal.c:debug_function() curl: STATE: WAITPERFORM =>
PERFORM handle 0x78d40924; (connection #0)
flimflamd[13289]: src/portal.c:debug_function() curl: additional stuff not
fine transfer.c:1036: 0 0
flimflamd[13289]: src/portal.c:socket_callback() FD#10 action=1
flimflamd[13289]: src/portal.c:source_dispatch() mcode = 0, remaining = 1
flimflamd[13289]: src/portal.c:debug_function() curl: HTTP 1.1 or later
with persistent connection, pipelining supported
flimflamd[13289]: src/portal.c:debug_function() curl: STATE: PERFORM =>
DONE handle 0x78d40924; (connection #0)
flimflamd[13289]: src/portal.c:debug_function() curl: Closing connection #0
flimflamd[13289]: src/portal.c:socket_callback() FD#10 action=4
flimflamd[13289]: src/portal.c:socket_callback() FD#10 unset (using slot 1)
flimflamd[13289]: src/portal.c:source_dispatch() mcode = 0, remaining = 0
flimflamd[13289]: src/portal.c:get_http_code() http response code is 204
flimflamd[13289]: eth0: interface can route traffic, marking online
flimflamd[13289]: src/portal.c:should_process_request() SKIP, service
ethernet_687f74408236 state online != ready
flimflamd[13289]: src/portal.c:debug_function() curl: Expire cleared
flimflamd[13289]: src/portal.c:timer_callback() set timeout -1 ms (expires
2147483647.800275559)
^Cdhcpcd[13291]: received SIGINT, stopping
dhcpcd[13291]: eth0: removing interface
flimflamd[13289]: Terminating

chronos_at_localhost:/tmp sudo /usr/sbin/flimflamd --debug=portal -n

flimflamd[13294]: src/portal.c:portal_service_state_changed() eth0:
Checking http://clients3.google.com/generate_204 on ethernet_687f74408236
flimflamd[13294]: src/portal.c:portal_service_state_changed() eth0: Using
name servers 172.16.255.1,172.24.220.65,172.25.126.65
flimflamd[13294]: src/portal.c:portal_service_state_changed() curl
flimflamd[13294]: src/portal.c:timer_callback() set timeout 1 ms (expires
34361.966469959)
flimflamd[13294]: src/portal.c:debug_function() curl: About to connect() to
clients3.google.com port 80 (#0)
flimflamd[13294]: src/portal.c:debug_function() curl: Trying
2001:4860:4003:802::1006...
flimflamd[13294]: src/portal.c:debug_function() curl: Local Interface eth0
is ip fe80::6a7f:74ff:fe40:8236 using address family 10
flimflamd[13294]: src/portal.c:debug_function() curl: bind failed with
errno 99: Cannot assign requested address
flimflamd[13294]: src/portal.c:debug_function() curl: Trying
74.125.226.233...
flimflamd[13294]: src/portal.c:debug_function() curl: Local Interface eth0
is ip 172.31.194.38 using address family 2
flimflamd[13294]: src/portal.c:debug_function() curl: Local port: 0
flimflamd[13294]: src/portal.c:debug_function() curl: 0x77ea871c is at send
pipe head!
flimflamd[13294]: src/portal.c:debug_function() curl: STATE: CONNECT =>
WAITCONNECT handle 0x77eb9f7c; (connection #0)
flimflamd[13294]: src/portal.c:socket_callback() FD#9 action=2
flimflamd[13294]: src/portal.c:socket_callback() FD#9 set (using slot 0)
flimflamd[13294]: src/portal.c:timer_callback() set timeout 582 ms (expires
34362.590371366)
flimflamd[13294]: No previous default gateway, use 172.31.195.254
flimflamd[13294]: Set default route for eth0: gw 172.31.195.254 metric 0
flimflamd[13294]: eth0 {add} address 172.31.194.38/16 (af 2) label eth0
flimflamd[13294]: eth0 {del} address 172.31.194.38/16 (af 2) label eth0
flimflamd[13294]: eth0 {add} address 172.31.194.38/23 (af 2) label eth0
flimflamd[13294]: eth0 {add} route 0.0.0.0 gw 172.31.195.254 scope 0
<UNIVERSE>
flimflamd[13294]: src/portal.c:source_check_expiration() request has
timeout'ed
flimflamd[13294]: src/portal.c:source_check_expiration() request has
timeout'ed
flimflamd[13294]: src/portal.c:debug_function() curl: After 587ms connect
time, move on!
flimflamd[13294]: src/portal.c:debug_function() curl: Trying
74.125.226.234...
flimflamd[13294]: src/portal.c:debug_function() curl: Local Interface eth0
is ip 172.31.194.38 using address family 2
flimflamd[13294]: src/portal.c:debug_function() curl: Local port: 0
flimflamd[13294]: src/portal.c:timer_callback() set timeout 586 ms (expires
34363.204508379)
flimflamd[13294]: src/portal.c:source_dispatch() mcode = 0, remaining = 1
flimflamd[13294]: src/portal.c:debug_function() curl: Connected to
clients3.google.com (74.125.226.234) port 80 (#0)
flimflamd[13294]: src/portal.c:debug_function() curl: STATE: WAITCONNECT =>
DO handle 0x77eb9f7c; (connection #0)
flimflamd[13294]: src/portal.c:debug_function() curl: STATE: DO => DO_DONE
handle 0x77eb9f7c; (connection #0)
flimflamd[13294]: src/portal.c:debug_function() curl: STATE: DO_DONE =>
WAITPERFORM handle 0x77eb9f7c; (connection #0)
flimflamd[13294]: src/portal.c:debug_function() curl: STATE: WAITPERFORM =>
PERFORM handle 0x77eb9f7c; (connection #0)
flimflamd[13294]: src/portal.c:debug_function() curl: select/poll returned
error
flimflamd[13294]: src/portal.c:debug_function() curl: Closing connection #0
flimflamd[13294]: src/portal.c:socket_callback() FD#9 action=4
flimflamd[13294]: src/portal.c:socket_callback() FD#9 unset (using slot 0)
flimflamd[13294]: src/portal.c:source_dispatch() mcode = 0, remaining = 0
flimflamd[13294]: eth0: http_get_failed, curl code 55, marking portal
flimflamd[13294]: src/portal.c:should_process_request() SKIP, service
ethernet_687f74408236 state portal != ready
flimflamd[13294]: src/portal.c:debug_function() curl: Expire cleared
flimflamd[13294]: src/portal.c:timer_callback() set timeout -1 ms (expires
2147483647.648559200)
^Cdhcpcd[13296]: received SIGINT, stopping
dhcpcd[13296]: eth0: removing interface
flimflamd[13294]: Terminating

-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2012-01-25