Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

client_http_run_once example: use NEAT_RUN_ONCE #147

Closed
wants to merge 2 commits into from

Conversation

bagder
Copy link
Member

@bagder bagder commented Sep 1, 2016

This example extracts the backend fd and runs its own IO loop and
invokes neat_start_event_loop(ctx, NEAT_RUN_ONCE) for every action on
the backend fd.

NOTE this example doesn't seem to work and I would like someone to throw an eye on the example to see if the API is used wrongly and if so help me fix the example, or if the API is used correctly take a look at the NEAT code to see why it doesn't work!

This example is mostly a copy and paste from the client_http_get example and is supposed to be used with the exact same command line arguments.

This example extracts the backend fd and runs its own IO loop and
invokes neat_start_event_loop(ctx, NEAT_RUN_ONCE) for every action on
the backend fd.
@oystedal
Copy link
Contributor

oystedal commented Sep 1, 2016

I'd normally take on an issue like this, however, I'm currently busy on another part of the project. I might be able to look at this next month, depending on circumstances, unless someone else has a look at this.

I glanced quickly over the code, and I think your approach should work, ideally. I don't find the fact that it doesn't work surprising, since it's a use case that hasn't really been looked into yet.

Libuv does have an example program where an event loop is embedded inside another. I don't have the link at hand, but if you find it, you could give it a spin and check if that example works, just to rule out the possibility that libuv doesn't support it on your system.

@bagder
Copy link
Member Author

bagder commented Sep 1, 2016

Thanks, that was useful input anyway and I'll proceed and write up a more raw libuv using snippet and see if that works for me before digging deeper into this.

I'll be back when I have more.

@bagder
Copy link
Member Author

bagder commented Sep 8, 2016

This probably doesn't test the exact same flow, but I wrote up a test code that uses libuv directly and I extract only the backend file descriptor to know when to act and it downloads my 512MB test file from a localhost web server just fine: https://gist.github.com/bagder/ffb613e3c3c5f41813b31fc09ef1c261

@weinrank
Copy link
Member

weinrank commented Sep 8, 2016

I just played a bit with the code from your PR:

  1. When i removed the rc > 1 condition and so neat_start_event_loop(ctx, NEAT_RUN_ONCE); is called after the timeout the code works.
  2. If I add POLLOUT to the poll events, the code also works.

This might not be a helpful contribution to the issue but maybe it helps...

@bagder
Copy link
Member Author

bagder commented Sep 8, 2016

Thanks!

Oh right, it definitely needs to call for the timeout case as well. Interesting that it needs POLLOUT as the documentation for epoll says it'll signal readable when there's something to do.

This will take me further!

@bagder
Copy link
Member Author

bagder commented Sep 8, 2016

When I invoke neat_start_event_loop even when it times out (1000 ms) it successfully downloads a URL. That seems like a good fix to the example code. (POLLOUT doesn't seem to make a difference for me)

However, when I try requesting a page from for example www.haxx.se which is my site, on a 2~ms RTT time from me and I have a fast DNS server accessible I still get two timeouts so the entire operation takes over 2 seconds for a 17 bytes response body. Shouldn't such a case be driven fine with socket activity alone without timeouts?

And it shows that for an app like this, exporting a "maximum time to wait" timeout value in the API would be useful.

... makes the example work, albeit a bit slow.
@weinrank
Copy link
Member

weinrank commented Sep 8, 2016

How about this:
9d1f8a2

  • POLLOUT makes a difference for me
  • if rc>0 run it once
  • on timeout do nothing

Works for me and this specific example - might be the wrong strategy in a bigger picture.

@bagder
Copy link
Member Author

bagder commented Sep 8, 2016

You on Linux too? Because that does not work for me! If I make the change "on timeout do nothing", my test just stops doing anything after 1.2 milliseconds and then loops around timeouts. The other two changes don't have any effect for my test case. Puzzling!

In my case, my target host name returns AAAA entries from DNS but IPv6 doesn't work but I can't think of much other things that are out of the ordinary.

@bagder
Copy link
Member Author

bagder commented Sep 8, 2016

output from the example when tested against www.haxx.se from my machine just now

@weinrank
Copy link
Member

weinrank commented Sep 8, 2016

OSX, on Linux the behavior is exactly how you mentioned... mh...

@bagder
Copy link
Member Author

bagder commented Sep 22, 2016

The POLLOUT thing is probably just related to the fact that epoll on Linux doesn't need it, but whatever is used on mac needs that. An unfortunate platform difference but then adding POLLOUT to the example's use of poll() doesn't affect anything on Linux so it should be fine.

When I increase the timeout and add some more instrumental printf() debugging, it is obvious that we don't get the epoll backend fd to trigger action when there's incoming UDP responses for the name resolves. Only once we call neat again after a time-out, the loop runs and then it handles the received DNS responses. With a 5000 ms timeout I can see this:

[   0.000899][DBG] neat_run_event_cb
[   0.000928][INF] uv_udp_recv_start was called
[   0.000968][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.000981][INF] uv_udp_recv_start was called
[   0.001008][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001023][INF] uv_udp_recv_start was called
[   0.001048][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001061][INF] uv_udp_recv_start was called
[   0.001086][DBG] neat_resolver_send_query - Request for haxx.se sent
Waiting on 1 streams...
[   5.003691][DBG] neat_start_event_loop
[   5.003769][INF] neat_resolver_dns_recv_cb entered
[   5.003800][INF] neat_resolver_dns_recv_cb entered
[   5.003805][INF] neat_resolver_dns_recv_cb entered
[   5.003816][INF] neat_resolver_dns_recv_cb entered

I have yet to figure out why this is so. I added the uv_udp_recv_start was called outputs just to see how the UDP handle is added to libuv and from all I can tell, that should be enough.

And then it goes on a little further and returns out from the loop again only to not trigger on anything further and it'll sit through another time-out:

[   5.007517][INF] neat_resolver_dns_recv_cb entered
[   5.007525][INF] neat_resolver_dns_recv_cb entered
[   5.007537][INF] neat_resolver_dns_recv_cb entered
Waiting on 1 streams...
[  10.007787][DBG] neat_start_event_loop
[  10.007825][DBG] he_resolve_cb
[  10.007844][INF] Happy-Eyeballs results:
[  10.007860][INF]      IPv4 - 192.168.0.192:0 -> 80.67.6.50:80
[  10.007891][DBG] neat_connect
[  10.007949][INF] neat_connect: Bind fd 23 to 192.168.0.192

... and from hereon everything looks sensible.

@bagder
Copy link
Member Author

bagder commented Oct 10, 2016

this example is now broken due to API updates, see also #162

@bagder
Copy link
Member Author

bagder commented Oct 10, 2016

After I fix the neat_set_property use so that it builds again, this example now takes 15 seconds...

@oystedal
Copy link
Contributor

Takes two seconds for me.

@bagder
Copy link
Member Author

bagder commented Oct 10, 2016

On Linux? And I should clarify that it takes 15 seconds with 5 seconds poll waits, which means that it times out three times. if we lower the timeout it'll of course run faster. (I'm on Linux kernel 4.5.4 without IPv6 working).

Two seconds sounds like it triggered at least two timeouts for you as well?

@oystedal
Copy link
Contributor

The new Happy Eyeballs code is timeout-based (currently 10ms between each connection attempt), so if you specify excessive timeouts it is certainly going to slow things down. I would assume this is where uv_backend_timeout() comes into play. I'll give it a shot, and if it works, I'll expose it alongside the backend fd.

@oystedal
Copy link
Contributor

Give this a try: 80cef52

@bagder
Copy link
Member Author

bagder commented Oct 11, 2016

That's helpful! It removed all but one longer wait. With added debug output that tells when it has exited poll due to timeout and how long the timeout was, it starts out like this:

[   0.000001][INF] neat_log_init - NEAT_LOG_LEVEL : default
[   0.000039][INF] neat_log_init - opening logfile ...
[   0.000047][DBG] neat_init_ctx
[   0.000268][DBG] neat_new_flow
[   0.000299][DBG] neat_set_property
[   0.000338][DBG] neat_set_operations
[   0.000348][DBG] updatePollHandle
[   0.000356][DBG] neat_open
[   0.000366][DBG] neat_add_event_cb
[   0.000374][INF] neat_add_event_cb - Added new callback for event type 0
[   0.000382][DBG] neat_add_event_cb
[   0.000389][INF] neat_add_event_cb - Added new callback for event type 2
[   0.000453][INF] Added 192.168.0.1 to resolver list
[   0.000470][DBG] neat_add_event_cb
[   0.000478][INF] neat_add_event_cb - Added new callback for event type 0
[   0.000486][DBG] send_properties_to_pm
[   0.000583][DBG] Added endpoint "127.0.0.1@lo" to PM request
[   0.000599][DBG] Added endpoint "192.168.0.192@eth0" to PM request
[   0.000611][DBG] Added endpoint "::1@lo" to PM request
[   0.000660][DBG] fe80::3285:a9ff:fe46:b619%eth0 is a link-local address, skipping
[   0.000678][DBG] neat_json_send_once
[   0.000709][DBG] neat_unix_json_socket_open
[   0.000719][DBG] Opening UNIX socket /home/daniel/.neat/neat_pm_socket
Opened flow 0
[   0.000755][DBG] neat_start_event_loop
[   0.000765][DBG] on_unix_json_connected
[   0.000774][DBG] Failed to connect to UNIX socket
[   0.000782][DBG] on_pm_error
[   0.000789][DBG] on_pm_error
[   0.000796][DBG] ===== Unable to communicate with PM, using fallback =====
[   0.000808][ERR] neat_start_request - No available src addresses
[   0.000851][INF] Available src-addresses:
[   0.000864][INF]  IPv4: 127.0.0.1/8
[   0.000872][DBG] neat_run_event_cb
[   0.001069][INF] uv_udp_recv_start was called
[   0.001120][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001137][INF] uv_udp_recv_start was called
[   0.001166][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001186][INF] uv_udp_recv_start was called
[   0.001217][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001236][INF] uv_udp_recv_start was called
[   0.001264][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001279][INF] uv_udp_recv_start was called
[   0.001320][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001336][INF] Available src-addresses:
[   0.001345][INF]  IPv4: 192.168.0.192/24
[   0.001353][INF]  IPv4: 127.0.0.1/8
[   0.001361][DBG] neat_run_event_cb
[   0.001394][INF] uv_udp_recv_start was called
[   0.001423][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001442][INF] uv_udp_recv_start was called
[   0.001468][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001493][INF] uv_udp_recv_start was called
[   0.001521][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001539][INF] uv_udp_recv_start was called
[   0.001565][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001580][INF] uv_udp_recv_start was called
[   0.001609][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001630][INF] Available src-addresses:
[   0.001639][INF]  IPv6: ::1/128 pref 4294967295 valid 4294967295
[   0.001647][INF]  IPv4: 192.168.0.192/24
[   0.001655][INF]  IPv4: 127.0.0.1/8
[   0.001663][DBG] neat_run_event_cb
[   0.001712][INF] uv_udp_recv_start was called
[   0.001736][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001752][INF] uv_udp_recv_start was called
[   0.001772][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001789][INF] uv_udp_recv_start was called
[   0.001809][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001825][INF] uv_udp_recv_start was called
[   0.001845][DBG] neat_resolver_send_query - Request for haxx.se sent
[   0.001859][DBG] on_pipe_close
[   0.001868][DBG] on_pm_close
[   0.001879][DBG] neat_get_backend_fd
[   0.001889][DBG] neat_get_backend_timeout
Waited 0 on 1 streams...
[   0.001902][DBG] neat_start_event_loop
[   0.001927][DBG] neat_get_backend_timeout
[   0.002041][DBG] neat_start_event_loop
[   0.002062][INF] neat_resolver_dns_recv_cb entered
[   0.002129][INF] neat_resolver_dns_recv_cb entered
[   0.002148][DBG] neat_get_backend_timeout
[   0.002950][DBG] neat_start_event_loop
[   0.002969][INF] neat_resolver_dns_recv_cb entered
[   0.002992][INF] neat_resolver_dns_recv_cb entered
[   0.003002][DBG] neat_get_backend_timeout
[   0.003825][DBG] neat_start_event_loop
[   0.003841][INF] neat_resolver_dns_recv_cb entered
[   0.003860][INF] neat_resolver_dns_recv_cb entered
[   0.003870][DBG] neat_get_backend_timeout
[   0.004086][DBG] neat_start_event_loop
[   0.004119][INF] neat_resolver_dns_recv_cb entered
[   0.004150][INF] neat_resolver_dns_recv_cb entered
[   0.004161][DBG] neat_get_backend_timeout
[   0.005128][DBG] neat_start_event_loop
[   0.005192][DBG] neat_get_backend_timeout
[   0.013549][DBG] neat_start_event_loop
[   0.013592][INF] neat_resolver_dns_recv_cb entered
[   0.013628][INF] neat_resolver_dns_recv_cb entered
[   0.013638][DBG] neat_get_backend_timeout
[   0.015582][DBG] neat_start_event_loop
[   0.015609][INF] neat_resolver_dns_recv_cb entered
[   0.015637][INF] neat_resolver_dns_recv_cb entered
[   0.015646][DBG] neat_get_backend_timeout
[   0.032398][DBG] neat_start_event_loop
[   0.032422][INF] neat_resolver_dns_recv_cb entered
[   0.032444][INF] neat_resolver_dns_recv_cb entered
[   0.032452][DBG] neat_get_backend_timeout
[   0.032584][DBG] neat_start_event_loop
[   0.032610][INF] neat_resolver_dns_recv_cb entered
[   0.032633][INF] neat_resolver_dns_recv_cb entered
[   0.032642][DBG] neat_get_backend_timeout
[   0.032754][DBG] neat_start_event_loop
[   0.032780][INF] neat_resolver_dns_recv_cb entered
[   0.032813][INF] neat_resolver_dns_recv_cb entered
[   0.032823][DBG] neat_get_backend_timeout
[   0.032832][DBG] neat_start_event_loop
[   0.032841][INF] neat_resolver_dns_recv_cb entered
[   0.032854][INF] neat_resolver_dns_recv_cb entered
[   0.032862][DBG] neat_get_backend_timeout
Waited 967 on 1 streams...
[   1.000898][DBG] neat_start_event_loop
[   1.000919][DBG] neat_get_backend_timeout
Waited 1 on 1 streams...
[   1.002022][DBG] neat_start_event_loop
[   1.002046][DBG] open_resolve_cb
[   1.002093][DBG] HE Candidate  0:       lo [ 1]      TCP/IPv4 <saddr 127.0.0.1> <dstaddr 80.67.6.50> port    80 priority 0
[   1.002104][DBG] HE Candidate  1:     eth0 [ 2]      TCP/IPv4 <saddr 192.168.0.192> <dstaddr 80.67.6.50> port    80 priority 1
[   1.002112][DBG] HE will now commence


[   1.002118][DBG] neat_connect
[   1.002134][INF] neat_connect: Bind fd 24 to 127.0.0.1
[   1.002152][WRN] Could not bind fd 24 socket to interface lo
[   1.002179][DBG] neat_connect: Connect failed for fd 24 connect error (22): Invalid argument
[   1.002188][DBG] neat_he_open: Connect failed with ret = -2
[   1.002195][DBG] neat_he_open:Release candidate
[   1.002203][DBG] neat_free_candidate
[   1.002214][INF] uv_udp_recv_stop was called
[   1.002229][INF] uv_udp_recv_stop was called
[   1.002241][INF] uv_udp_recv_stop was called
[   1.002251][INF] uv_udp_recv_stop was called
[   1.002271][INF] uv_udp_recv_stop was called
[   1.002281][INF] uv_udp_recv_stop was called
[   1.002292][INF] uv_udp_recv_stop was called
[   1.002302][INF] uv_udp_recv_stop was called
[   1.002311][INF] uv_udp_recv_stop was called
[   1.002321][INF] uv_udp_recv_stop was called
[   1.002331][INF] uv_udp_recv_stop was called
[   1.002341][INF] uv_udp_recv_stop was called
[   1.002351][INF] uv_udp_recv_stop was called
[   1.002361][INF] uv_udp_recv_stop was called
[   1.002377][DBG] free_handle_cb
[   1.002386][DBG] neat_get_backend_timeout
Waited 0 on 1 streams...
[   1.002396][DBG] neat_start_event_loop
[   1.002405][DBG] neat_get_backend_timeout
Waited 9 on 1 streams...
[   1.011496][DBG] neat_start_event_loop
[   1.011506][DBG] neat_connect
[   1.011522][INF] neat_connect: Bind fd 15 to 192.168.0.192
[   1.011542][WRN] Could not bind fd 15 socket to interface eth0

@oystedal
Copy link
Contributor

The longer timeout is a timeout in the DNS resolver code, which is as intended at this point. You may ignore that for now.

@kristrev
Copy link
Contributor

Note that any timeout value in the DNS resolver has been chosen by random and can be changed at will.

@oystedal
Copy link
Contributor

This PR has been dormant for quite some time now. What is the current status?

  • Should this be merged? I would say yes, but then it should probably also be added to the test as well.
  • Are there any other bugs/shortcomings preventing the use of NEAT_RUN_ONCE? I'll add the function for getting the backend fd timeout to the master branch if needed.

@bagder
Copy link
Member Author

bagder commented Nov 25, 2016

I really need to use the RUN_ONCE approach for using NEAT in Firefox and to make that API work I need to know the timeout value one way or another. So I think having an example using that method of driving neat is a good idea.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants