fennb/phirehose

Catch 420

Closed this issue · 14 comments

When Twitter has rate-limited the app, it responds with error 420. This error is not caught by phirehose and can lead to rate destruction as it attempts to reconnect again and again after having been rate-limited.

fennb commented

Hey there,

Phirehose currently behaves the same on all errors (ie: anything not a HTTP 200/OK) and should continually back-off reconnect attempts until it hits httpBackoffMax (240 seconds).

Is this not the behaviour you are seeing/wanting?

The reconnect attempts are happening too frequent inside of those two minutes for 420 errors, this ends up eating up the connection rate limit for streams (which take 15 minutes to cool down on Twitter's end) this leaves the app in a state of 420 for an even longer period of time due to the rejected reconnect attempts.

The reconnect attempts are happening too frequent inside of those two
minutes...

Sounds strange. Can you record the times of each of the reconnect
attempts that you see? That might give a clue where the bug is.

There is no chance you have 2+ instances running? Or 2+ servers
connecting using the same account?

Darren

Darren Cook, Software Researcher/Developer
My new book: Data Push Apps with HTML5 SSE
Published by O'Reilly: (ask me for a discount code!)
http://shop.oreilly.com/product/0636920030928.do
Also on Amazon and at all good booksellers!

No, I only have one instance running. Unfortunately, it's really hard to tell if this is the problem because the only error being logged is the Undefined Index error I also reported. This issue seems to occur when twitter is responding with a 420, however, the http code isn't being logged. If I use XDebug and set a breakpoint, then i can get the message out of twitter (that it's 420 and to enhance calm but, if Xdebug is running a second service of the script, that could be the cause of the 420)

However, If I step through with xdebug, sometimes I get a 200 back and on that 200, it's able to parse one or two tweets. When I'm not getting a 200 back, I get the undefined index error.

But, here is the log so far:

[12-May-2015 12:45:06 America/Los_Angeles] PHP Notice: Undefined offset: 2 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:45:06 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:45:06 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:45:06 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:45:06 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:45:06 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:45:06 America/Los_Angeles] PHP Notice: Undefined offset: 1 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:45:06 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:45:06 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:45:06 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:45:06 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:45:06 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:45:06 America/Los_Angeles] Phirehose: HTTP failure 1 of 20 connecting to stream: HTTP ERROR : (). Sleeping for 10 seconds.
[12-May-2015 12:45:16 America/Los_Angeles] Phirehose: Connecting to twitter stream: https://stream.twitter.com/1.1/statuses/filter.json with params: array ( 'track' => 'mirakaddoura,thewonderclock,wonderclock', 'follow' => '585866255',)
[12-May-2015 12:45:17 America/Los_Angeles] Phirehose: Connecting to ssl://stream.twitter.com, port=443, connectTimeout=5
[12-May-2015 12:45:17 America/Los_Angeles] Phirehose: Connection established to stream.twitter.com
[12-May-2015 12:45:17 America/Los_Angeles] Phirehose: POST /1.1/statuses/filter.json HTTP/1.1
Host: stream.twitter.com:443
Connection: Close
Content-type: application/x-www-form-urlencoded
Content-length: 66
Accept: /
Authorization: OAuth realm="",oauth_consumer_key="PphRdi8Rr40RVoTPKY9IZhIhX",oauth_nonce="59df38ac95753c4c93aa8e0e33fb3e5c",oauth_signature_method="HMAC-SHA1",oauth_timestamp="1431459917",oauth_version="1.0A",oauth_token="585866255-gqrhwljiPXt1spNWsc2vnOexUTeAykHBEv2NkYH0",oauth_signature="qCkHM7DxVhv7zg8mDwa9Z9qFhkQ%3D"
User-Agent: Phirehose/1.0RC +https://github.com/fennb/phirehose

track=mirakaddoura%2Cthewonderclock%2Cwonderclock&follow=585866255

[12-May-2015 12:45:17 America/Los_Angeles] PHP Notice: Undefined offset: 2 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:45:17 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:45:17 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:45:17 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:45:17 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:45:17 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:45:17 America/Los_Angeles] PHP Notice: Undefined offset: 1 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:45:17 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:45:17 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:45:17 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:45:17 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:45:17 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:45:17 America/Los_Angeles] Phirehose: HTTP failure 2 of 20 connecting to stream: HTTP ERROR : (). Sleeping for 20 seconds.
[12-May-2015 12:45:37 America/Los_Angeles] Phirehose: Connecting to twitter stream: https://stream.twitter.com/1.1/statuses/filter.json with params: array ( 'track' => 'mirakaddoura,thewonderclock,wonderclock', 'follow' => '585866255',)
[12-May-2015 12:45:37 America/Los_Angeles] Phirehose: Connecting to ssl://stream.twitter.com, port=443, connectTimeout=5
[12-May-2015 12:45:37 America/Los_Angeles] Phirehose: Connection established to stream.twitter.com
[12-May-2015 12:45:37 America/Los_Angeles] Phirehose: POST /1.1/statuses/filter.json HTTP/1.1
Host: stream.twitter.com:443
Connection: Close
Content-type: application/x-www-form-urlencoded
Content-length: 66
Accept: /
Authorization: OAuth realm="",oauth_consumer_key="PphRdi8Rr40RVoTPKY9IZhIhX",oauth_nonce="c628e9436242b4e0f8c88f6aaee22811",oauth_signature_method="HMAC-SHA1",oauth_timestamp="1431459937",oauth_version="1.0A",oauth_token="585866255-gqrhwljiPXt1spNWsc2vnOexUTeAykHBEv2NkYH0",oauth_signature="9Hsn0GBtWuohuCsLU24eMozpckE%3D"
User-Agent: Phirehose/1.0RC +https://github.com/fennb/phirehose

track=mirakaddoura%2Cthewonderclock%2Cwonderclock&follow=585866255

[12-May-2015 12:45:37 America/Los_Angeles] PHP Notice: Undefined offset: 2 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:45:37 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:45:37 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:45:37 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:45:37 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:45:37 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:45:37 America/Los_Angeles] PHP Notice: Undefined offset: 1 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:45:37 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:45:37 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:45:37 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:45:37 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:45:37 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:45:37 America/Los_Angeles] Phirehose: HTTP failure 3 of 20 connecting to stream: HTTP ERROR : (). Sleeping for 40 seconds.
[12-May-2015 12:46:17 America/Los_Angeles] Phirehose: Connecting to twitter stream: https://stream.twitter.com/1.1/statuses/filter.json with params: array ( 'track' => 'mirakaddoura,thewonderclock,wonderclock', 'follow' => '585866255',)
[12-May-2015 12:46:17 America/Los_Angeles] Phirehose: Connecting to ssl://stream.twitter.com, port=443, connectTimeout=5
[12-May-2015 12:46:17 America/Los_Angeles] Phirehose: Connection established to stream.twitter.com
[12-May-2015 12:46:17 America/Los_Angeles] Phirehose: POST /1.1/statuses/filter.json HTTP/1.1
Host: stream.twitter.com:443
Connection: Close
Content-type: application/x-www-form-urlencoded
Content-length: 66
Accept: /
Authorization: OAuth realm="",oauth_consumer_key="PphRdi8Rr40RVoTPKY9IZhIhX",oauth_nonce="86150ff8a5102bb0466050dec9a0c8bc",oauth_signature_method="HMAC-SHA1",oauth_timestamp="1431459977",oauth_version="1.0A",oauth_token="585866255-gqrhwljiPXt1spNWsc2vnOexUTeAykHBEv2NkYH0",oauth_signature="EKNZ%2BDFPX8TLDBeaj3WyPeET%2F%2Fw%3D"
User-Agent: Phirehose/1.0RC +https://github.com/fennb/phirehose

track=mirakaddoura%2Cthewonderclock%2Cwonderclock&follow=585866255

[12-May-2015 12:46:17 America/Los_Angeles] PHP Notice: Undefined offset: 2 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:46:17 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:46:17 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:46:17 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:46:17 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:46:17 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:46:17 America/Los_Angeles] PHP Notice: Undefined offset: 1 in C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php on line 689
[12-May-2015 12:46:17 America/Los_Angeles] PHP Stack trace:
[12-May-2015 12:46:17 America/Los_Angeles] PHP 1. {main}() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:0
[12-May-2015 12:46:17 America/Los_Angeles] PHP 2. Phirehose->consume() C:\xampp\htdocs\wonderclock\twitterminer\db\get_tweets.php:63
[12-May-2015 12:46:17 America/Los_Angeles] PHP 3. Phirehose->reconnect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:411
[12-May-2015 12:46:17 America/Los_Angeles] PHP 4. Phirehose->connect() C:\xampp\htdocs\wonderclock\vendor\fennb\phirehose\lib\Phirehose.php:824
[12-May-2015 12:46:17 America/Los_Angeles] Phirehose: HTTP failure 4 of 20 connecting to stream: HTTP ERROR : (). Sleeping for 80 seconds.

The log says line 689 instead of 688 because I tried to move the fgets above the preg_replace in an attempt to nail down a more specific reason for the error.

When this error occurs, I don't get any tweets from the user I've marked, however as I said above, when I step through with XDebug and get a 400, I get the tweets until I stop stepping through and the undefined indexes begin again.

The log says line 689 instead of 688

https://github.com/fennb/phirehose/blob/master/lib/Phirehose.php#L689

because I tried to move the
fgets above the preg_replace in an attempt to nail down a more
specific reason for the error.

That's exactly what I wanted to know. I.e. change line 689 to be:

$firstLine = fgets($this->conn, 1024);
$firstLineParts = preg_split('/\s+/', trim($firstLine) );
if(count($firstLineParts)!=3){
$this->log('BAD firstLine="'.$firstLine.'"');
$connectFailures++;
$httpRetry = ($httpRetry < $this->httpBackoffMax) ?
$httpRetry * 2 : $this->httpBackoffMax;
sleep($httpRetry);
continue;
}
list($httpVer, $httpCode, $httpMessage) = $firstLineParts;

(untested, but I think that makes a reasonable patch, as it does not
remove or alter any existing functionality.)

Darren

Now it's saying undefined variable httpCode line: 745

But what was the value of firstLine in the log() (assuming you did the above patch)? (I just fixed a typo in it, by the way)

Bad firstLine = ""

Bad firstLine = ""

Perhaps you could write a hack to get the next line if it reads a blank
line, and let us know how it goes? I.e. if the next line contains the
header we were expecting, then that is a fix. (I'd have to go back and
read the http protocol, but perhaps a blank line is even valid at this
point??)

...still doesn't explain why only you are seeing this. Are you
connecting through a proxy? Or anything else you can think of that is
unusual? (Twitter have been known to introduce new server software
gradually, with little or no warning, so it is not impossible this is
something new that will affect everyone in the next week...)

Darren

Hmm, I'll give that a try and see if I can get some more information out of it.

In the meantime, twitter's streaming api says this about blank lines:
Blank lines
On slow streams, some messages may be blank lines which serve as “keep-alive” signals to prevent clients and other network infrastructure from assuming the stream has stalled and closing the connection.

Also, no proxy connections or anything like that. Just a regular hook-up to broadband through a wireless router. Windows 8.1. Using command to run the script.

fennb commented

Regarding reconnects, it does indeed appear that Twitter has updated recommendations regarding reconnections:

  • Back off linearly for TCP/IP level network errors. These problems are generally temporary and tend to clear quickly. Increase the delay in reconnects by 250ms each attempt, up to 16 seconds.
  • Back off exponentially for HTTP errors for which reconnecting would be appropriate. Start with a 5 second wait, doubling each attempt, up to 320 seconds.
  • Back off exponentially for HTTP 420 errors. Start with a 1 minute wait and double each attempt. Note that every HTTP 420 received increases the time you must wait until rate limiting will no longer will be in effect for your account.

Based on that, you're absolutely right @Schenn, Phirehose should respond slightly differently for 420 errors and back off more quickly.

I'm having the same issue. Any solution yet?