mm-record doesn't seem to work with github.com

[adnan-ahmed]

I have been trying to debug mm-record but I cannot seem to figure out the issue. I think I have pinpointed the issue so I would really appreciate any insight on where the problem might be coming from.

How to recreate

• I simply start a record shell using mm-record
• Initially I was fully load the https://github.com page. Upon inspection, I found out that the assets from the subdomain https://github.githubassets.com were not going through
• We can therefore simply initiate a request for a particular asset via curl. In this case, I picked
  curl -k https://github.githubassets.com/images/modules/site/icons/footer/twitter.svg
• However, the above request doesn't go through

My thoughts
I have used wireshark and modified the code to put print statements to identify where the problem might be.
It seems that when we register the actions in http_proxy.cc and poll for input/output events in poller.cc, after all the SSL handling, there is an incoming read on the fd opened on the server side (even before the GET request is read on the client-side fd).
This causes the read (from secure_socket.cc) to be called by the poller.cc which doesn't really receive any data and keeps blocking the process from moving further. The GET request from the client is never read (or read after a really long time which I am not sure why that's happening).
I am not sure what is causing this initial read from the server-side mm-record socket.

I have noticed this on multiple websites. Pinterest might be doing the same thing as I cannot load that page from within mm-webrecord either.

I am attaching some logs (print statements I put in the mahimahi source code) to get an idea of what's happening. I hope these can provide an idea of what I am seeing...

[HTTPProxy] New TCP (thread) initiated; src: 172.19.0.2:38548, dst: 185.199.110.154:443.
[HTTPProxy] TLS handling beginning.
[SecureSocket] connect completed
[HTTPProxy] TLS handling finished.

New loop created in response to the GET request
[HTTPProxy] Starting a loop with server: 11, client: 10, server_addr: 185.199.110.154:443
[HTTPProxy] Looping loop_id: 10_11, requests_received: 0, requests_completed: 0, client open: 1, server open: 1.
[Poller] polling for input on 11.
[Poller] polling for input on 10.
[Poller] not interested/not active on 11.
[Poller] not interested/not active on 10.
[Poller] input can be read from 11. <-- This is what I was talking about. Something is available to be read from server-side fd
[Poller] input can be read from 10.
[Poller] calling the callback at the fd 11
[HTTPProxy] Reading a response from server. <-- The callback is initiated by the poller.cc on the server-side fd.
[SecureSocket] read is called <-- The read is called from secure_socket.cc. This takes a really really long time (minutes on end)
[SecureSocket] read the data <-- It eventually goes through but doesnt really receive any data.
[HTTPProxy] Response read from server for . <-- the data received should be printed after "server for "
[HTTPProxy] Response parsed from server for.
[Poller] calling the callback at the fd 10 <-- now the poller.cc goes on to respond to the input on the client-side fd
[HTTPProxy] Reading a request from client. <-- callback is called from http_proxy.cc
[SecureSocket] read is called
[SecureSocket] read the data <-- read the data from the socket
v
++++++++++++++++++++++++++++++++++++++++++++++
read the request: GET /images/modules/site/icons/footer/twitter.svg HTTP/1.1
++++++++++++++++++++++++++++++++++++++++++++++

I haven't looked too deep into the logs below but they seem problematic too

[HTTPProxy] Looping loop_id: 10_11, requests_received: 0, requests_completed: 0, client open: 1, server open: 0.
[Poller] polling for input on 11.
[Poller] EOF occured on Direction::In on fd: 11.
[Poller] not interested/not active on 10.
[Poller] polling for output on 11.
[Poller] not interested/not active on 10.
[Poller] output can be written on 11.
[Poller] calling the callback at the fd 11
[Poller] wtf fd 11 is closed
[SecureSocket] write is called
[HTTPProxy] Looping loop_id: 10_11, requests_received: 1, requests_completed: 0, client open: 1, server open: 0.
[Poller] polling for input on 11.
[Poller] EOF occured on Direction::In on fd: 11.
[Poller] not interested/not active on 10.
[Poller] not interested/not active on 11.
[Poller] not interested/not active on 10.
[HTTPProxy] loop_id: 10_11 got an exit, client open: 1, server open: 0.
curl: (52) Empty reply from server

[keithw]

One known issue with mm-webrecord is that it doesn't work with TLS websites that require SNI. I don't know if this is related. @ravinet would probably know more.

[adnan-ahmed]

I am attaching the wireshark capture in case that might help. In the "working" alternate example, the 13th packet comes after the GET request. I realize that the 13th packet is an ACK to the 12th packet but it comes later for the working example.
Could it be that packet that "triggers" the poller to read from the server-side fd but cannot be read by the SSL_read?

I also tried to change the order in which the actions are registered in http_proxy.cc... I switched the server-in with client-in (essentially poll on the client-side fd first). Which did get rid of this problem but I think it still raised another issue which I can expand on as well if need be