"Too many forwards have been detected for this request."

[Jacek Jędrzejewski]

Strange bug occurs (we think it is a bug in diem but I couldn't find it) in a project we work on. From time to time the website suffers from "Too many forwards have been detected for this request." - this exception is thrown by symfony when diem's config value "site_active" ("Is the site ready for visitors") is false (btw. IMO we should do something about this situation ;) an "if statement" somewhere would be good IMO instead of "too many forwards" exception).

I thought one of our testers just used to turn off this option in admin settings panel but every settings change is logged and we have no config change log before logs about "Too many forwards" so it must happen somewhere else but dunno where. In the database the value of the record is NULL instead of "0" so it is.. cleared? Maybe cache clear? Before every such situation we have several "cache clear" log messages. 

Any ideas?

[4levels]

Hi Jacek,

Do you have any costumizations in your dmUser modules? Could it be caused by a session timeout, causing a redirect loop?  It's quite easy to deliberately create a redirect loop with symfony, so that this can happen uninted in case of session timeouts (eg. A widget redirecting to the login page, containing the same widget will redirect again and again..)

You can trigger an expired session by erasing the session cookie (with eg firecookie extension for firebug)

Just my 2 cents..

Regards,

Erik Van Kelst
IT specialist - OpenSource developer
--
sent from my mobile phone

[Jacek Jędrzejewski]

You know, that "Too many forwards have been detected for this request" is not the issue here. It's just an effect of "site_active" config value being cleared (nulled) - and that's the real issue here: what causes it, when and where.

[Stéphane]

Hi,

James is experiencing the same problem.

Do you run your website on a multi-sites webserver ? Is the APC instance shared ?

Regards,

2012/1/23 Jacek Jędrzejewski <jacek.jed...@gmail.com>

[Jacek Jędrzejewski]

Yup, it's our development server, we have several diem websites running on it, with APC enabled.

[James]

Hi Jacek, i have the same problem, for time at just hack the diem
system for resolve it,

in diem/dmCorePlugin/lib/config/dmConfig.php

public static function load($useCache = true)
{
.........
foreach($results as $result)
{
if (!isset(self::$config[$result[0]]) || isset(self::
$config[$result[0]]) && $result[2] == self::$culture)
{
self::$config[$result[0]] = $result[1];
}

}
//Modif Fuji too_many_forwards
$query = dmDb::pdo('UPDATE dm_setting_translation set value=1 WHERE
id=3');
unset($results);

self::$loaded = true;
}


regards

[Jacek Jędrzejewski]

Well, that's one of possible workarounds ;)

[i...@pimlicoplumbers.com]

My site got set to inactive again on Monday by a routine bot check.

[Jacek Jędrzejewski]

Found Kye's issue on diem bugtracker: http://community.diem-project.org/issues/90

[Florian GANTIER]

Hi Jacek,

I've encountered the same problem with unactivation of one of my websites recently. I really have thought it was an attack from someone. After checking my logs, it appears that the killing request came from someone visiting one of my pages from his IPhone.

The "site_active" setting was also set to NULL.

I am wondering if this issue, now not anymore appearing as an attack would have for origin an event. Is there any mean to see what event listener could modify this value?

Otherwise, I have checked if it would be possible to forge a form and send values to an admin form without beeing logged in, and it is impossible. The issue is somewhere else.

And, maybe it would be nice to be able to log events in prod environmenment as I couldn't succeed to activate it in 'front/config/settings.yml' by putting 'logging_enabled: true' . It works only in dev. Therefore I don't have details of all actions in front or admin before the issue occurs, which from my point of view and specially for admin is a potential security issue.

Florian

[Stéphane]

To have logging enabled in prod, you have to set the right logger class in factories.yml.

Regards,

[Jacek Jędrzejewski]

I doubt it is an attack because it happened also on our development server.

[Florian GANTIER]

Yes, I believe you. It happened only one time for me -the site isn't very much visited-, but was still surprinsing...

[Florian Gantier]

Thanks, works great!

[Stéphane]

To debunk this problem, I gess the best fit would be to :

• overload dmSetting project-class and its postSave() method
• adding a if($this->name == 'site_active')
  
• log the debug_backtrace()
• log the listeners for the settings modifications
• sitback, wait & relax

What more can be done to debunk this ?

Regards,

[Florian Gantier]

Hi,

I have analyzed the code today. It appears for me that there are not many places where the event 'dm.config.updated' is fired ie only in dmCorePlugin/lib/config/dmConfig.php in the set() method.

One way to have a NULL value is by trying to get a setting using dmConfig::get($name, $default = null). If the value doesn't exist, it will set the default value which is NULL when using the default parameter, if this last one isn't specified during the call.

There are only two files where dmConfig::get('site_active') is called: BasedmFrontActions.class.php and dmFrontBaseActions.php . In none of these files is a default value specified during the calls. And it is the same also for 'site_name', and I think other settings...

Florian

[Jacek Jędrzejewski]

Yea, I also noticed that settings like site_name are cleared at the same time as site_active. But what is the reason? Is it APC?

[Florian Gantier]

By continuing in the code, I attain the load() method which attemps to load the settings based on the main language. If this main language isn't found properly then the requests cannot work.

sfConfig::get('sf_default_culture') and sfContext are two potential sources of this problem. Diem actually overrides main Symfony language in initConfiguration() method of dmCorePlugin/lib/config/dmApplicationConfiguration.php and also eventually in dmThread class which is used in dmSeoSynchronizer.

Now, I am not quite sure if sfConfig and sfContext use APC (which is by me activated).

I have tried for example to modify the configuration file cache/prod/config_dm_config.yml.php changing my default language ('dm_i18n_cultures' like in dmApplicationConfiguration.php) which is 'fr' to 'en' and have got the exact 'Too many forwards have been detected for this request.' exception without logged config change (normal, dmConfig::set() isn't called and this doesn't save anything in DB).

[Stéphane]

Hi,

I have tried for example to modify the configuration file cache/prod/config_dm_config.

yml.php changing my default language ('dm_i18n_cultures' like in dmApplicationConfiguration.php) which is 'fr' to 'en' and have got the exact 'Too many forwards have been detected for this request.' exception without logged config change (normal, dmConfig::set() isn't called and this doesn't save anything in DB).

So what are the actions being called and forward to and by, and why ?

Regards,

[Florian Gantier]

I am just calling the homepage in Front:

'module' => 'dmFront', 'action' => 'page', 'slug' => '',

I cannot see more details in the redirects (maybe there is a mean), and when I activate the 'web_debug' in prod, the error doesn't show up. The error itself showing in homepage is a "401 Unauthorized".

[Florian Gantier]

In fact, there is the same redirect error in the log when web_debug is activated, but not the pink error screen.

Le 26/02/2012 23:34, Stéphane a écrit :

[Roozbeh Baabakaan]

hi
i have same problem with "Too many forwards have been detected for this request"
and it came from

/config/dm/config.yml

when i am swap 'fa' and 'en'

all:

i18n:
cultures: [ 'en','fa' ]

any other way to change default language of site ?

[Florian Gantier]

Did you try 'dm:setup'? It seems to write the settings for the missing
langues in dm_setting_translation.

Florian

Le 06/03/2012 11:58, Roozbeh Baabakaan a �crit :

> hi
> i have same problem with "Too many forwards have been detected for this request"
> and it came from
>
> /config/dm/config.yml
>
> when i am swap 'fa' and 'en'
>
> all:
>
> i18n:
> cultures: [ 'en','fa' ]
>
> any other way to change default language of site ?
>
> On 2/27/12, Florian Gantier<florian...@gmail.com> wrote:
>> In fact, there is the same redirect error in the log when web_debug is
>> activated, but not the pink error screen.
>>

>> Le 26/02/2012 23:34, St�phane a �crit :

[Roozbeh Baabakaan]

i have found another solution !

just add

app/config/factories.yml

all:
  user:
    class: myUser
    param:
      default_culture: fa

and the language problem resolved .

[Florian GANTIER]

Hi again,

I've watched the code of dmConfig more closely. There are in addition
to my above remarks other cases that can break the settings. In the
load() method, even if one exception was raised, the config is
considered to be loaded. By myself throwing one exception in the try{}
it broke my settings the same way as reported ie. a succession of
settings suddently saved with the NULL value.

I don't know what could cause an exception of type PDOException or
Doctrine_Connection_Exception, but self::$loaded shoud be set to true
at the begin of the method and then set to false when an exception is
occuring.

I also propose the following modification for the get() method to not
save a NULL value if this one isn't in the configuration. This kind of
behavior doesn't exist natively in sfConfig, so why to save a NULL
value?

public static function get($name, $default = null)
{
if (!self::has($name))
{
if (null !== $default)
{
self::set($name, $default);
}
return $default;
}

return self::$config[$name];
}

So in general terms, I consider that the NULL value although possibly
set to NULL via the method set() should be banned otherwise. I don't
have also any precise example in mind/code where a NULL value would be
needed.

With my modifications, I can still edit the settings in admin form,
and be pretty confident that my settings won't be set to NULL for
nothing.

Florian

On Feb 27, 1:10 am, Florian Gantier <florian.gant...@gmail.com> wrote:
> In fact, there is the same redirect error in the log when web_debug is
> activated, but not the pink error screen.
>

> Le 26/02/2012 23:34, St�phane a �crit :

[Stéphane]

Where is the try/catch you are mentionning ? It should be thrown away and not being confined. Thus making the problem appearing in dev.

I want to be able to set NULL as default. I want my code to be thrown when loading causes an exception.

No ?

Regards,

[Florian GANTIER]

The try/catch I'm mentioning is in the load() method. It isn't apparent when beeing in 'prod', i don't have tested for 'dev'.

If you want to set NULL value from the get(), why not, it just throw the code as you say, but also crush the settings. I'm not sure what could throw an exception...

Florian

2012/4/23 Stéphane <stephan...@gmail.com>

[Florian GANTIER]

So, could you tell me how to write logs in non debug environnement to detect future errors? I don't have use them yet and I'm going to break my eyes watching in the code...

Florian

2012/4/23 Stéphane <stephan...@gmail.com>

[Stéphane]

Look at the factories.yml, copy/paste the dev: logger section in the prod: one.

Then in settings.yml, for prod, activate the logging.

Regards,

[Jacek Jędrzejewski]

Any updates on this "investigation"?

[Florian GANTIER]

No... It would be great to be able to reproduce this issue at will. It wasn't possible for me on a remote server. So maybe it would be possible locally.

Jacek, maybe we should first concentrate on the reproducibility...

Florian

2012/6/13 Jacek Jędrzejewski <jacek.jed...@gmail.com>

[Jacek Jędrzejewski]

Happend on prod server like 3 times in a row yesterday. I'm testing the solution with "default_culture" for user and even added it to settings.yml and so far it helps.

W dniu czwartek, 14 czerwca 2012 09:40:34 UTC+2 użytkownik Florian GANTIER napisał:

No... It would be great to be able to reproduce this issue at will. It wasn't possible for me on a remote server. So maybe it would be possible locally.

Jacek, maybe we should first concentrate on the reproducibility...

Florian

2012/6/13 Jacek Jędrzejewski

Any updates on this "investigation"?

[Florian Gantier]

Hi Jacek,

Bring in one or many of your Diem projects (the more the better probably...) this replacement for load() function of lib/vendor/diem/dmCorePlugin/lib/config/dmConfig.php, after having brought dmConfig.php back to original. It will generate a log.html file of 5-10 MB right in web/ directory with a full detail about where the error is coming from. There are a short and a full backtrace bypassing symfony error handling, but more efficient in my opinion.

Also please put back to original the settings and the default language, as you seem to say in your response as a way to fix the issue... the goal is to catch the error.

Once you'll get one or more errors logged with the 'Too many forwards...' (only the first error is interesting for each of the sites), just send me zip archive to my e-mail so that I can investigate further.

Regards,

Florian

 public static function load($useCache = true)
  {
    $trace = date('D, d M Y H:i:s') . " - <br />";
    $bTrigger = true;

    if (!self::$culture)
    {
      if (class_exists('dmContext', false) && dmContext::hasInstance() && $user = dmContext::getInstance()->getUser())
      {
        self::$culture = $user->getCulture();
        $trace .= 'if - <br />';
      }
      else
      {
        self::$culture = sfConfig::get('sf_default_culture');
        $trace .= 'else - <br />';
      }
    }
   
    $trace .= 'self:culture = ' . self::$culture . ' - <br />';
    $trace .= 'sfConfig::get(\'sf_default_culture\') = ' . sfConfig::get('sf_default_culture') . ' - <br />';

    try
    {
     
      if(self::$culture == sfConfig::get('sf_default_culture'))
      {
        $results = dmDb::pdo('SELECT s.name, t.value, t.lang FROM dm_setting s LEFT JOIN dm_setting_translation t ON t.id=s.id AND t.lang = ?',
        array(self::$culture))->fetchAll(PDO::FETCH_NUM);
        $trace .= 'dmDb request if - <br />';
      }
      else
      {
        $results = dmDb::pdo('SELECT s.name, t.value, t.lang FROM dm_setting s LEFT JOIN dm_setting_translation t ON t.id=s.id AND t.lang IN (?, ?)',
        array(self::$culture, sfConfig::get('sf_default_culture')))->fetchAll(PDO::FETCH_NUM);
        $trace .= 'dmDb request else - <br />';
      }
    }
    catch(PDOException $e)
    {
      $results = array();
      $trace .= 'got PDOException ' . $e->getMessage() . ' - <br />';
      $bTrigger = true;
    }
    catch(Doctrine_Connection_Exception $e)
    {
      $results = array();
      $trace .= 'got Doctrine_Connection_Exception ' . $e->getMessage() . ' - <br />';
     
      $bTrigger = true;
    }

    self::$config = array();
    foreach($results as $result)
    {
      if (!isset(self::$config[$result[0]]) || isset(self::$config[$result[0]]) && $result[2] == self::$culture)
      {
        self::$config[$result[0]] = $result[1];
      }
      if (!isset($result[1])) $bTrigger = true;
    }
    if (count($results) == 0) $bTrigger = true;
    if ($bTrigger)
    {
        $trace_backtrace='';
        foreach(debug_backtrace() as $k=>$v){
            if($v['function'] == "include" || $v['function'] == "include_once" || $v['function'] == "require_once" || $v['function'] == "require"){
                $trace_backtrace .= "#".$k." ".$v['function']."(".$v['args'][0].") called at [".$v['file'].":".$v['line']."]<br />";
            }else{
                $trace_backtrace .= "#".$k." ".$v['function']."() called at [".$v['file'].":".$v['line']."]<br />";
            }
        }
       
        $current_ob_content = ob_get_contents();
        ob_end_clean();
        ob_start();
        debug_print_backtrace();
        $full_trace_backtrace = ob_get_contents();
        ob_end_clean();
        ob_start();
        echo $current_ob_content;
       
        $trace .= var_export($results, true) . '<br />';
        $trace .= $trace_backtrace . '<br/>';
        $trace .= $full_trace_backtrace . '<br/>';
       
        $handle = @fopen('log.html', 'a');
        @fwrite($handle, $trace);
        @fclose($handle);
    }
   
    unset($results);

    self::$loaded = true;
  }

Florian

[Florian GANTIER]

And I forgot to say in the code, the first $bTrigger has to be set to false, not true, of course...

Florian

2012/6/17 Florian Gantier <florian...@gmail.com>

[Jacek Jędrzejewski]

I was about to say that everything works fine with culture changes but today it happened again so I installed your debugger and we have to wait.

[Florian GANTIER]

Ok...

2012/6/19 Jacek Jędrzejewski <jacek.jed...@gmail.com>

[Florian Gantier]

Hi Jacek,

Do you have any news about the triggering of the error?

Florian

[Jacek Jędrzejewski]

Still no.

JJ.

[Jacek Jędrzejewski]

It happened like 2 minutes ago, strange thing... But there is no log.html file!

W dniu piątek, 29 czerwca 2012 13:58:31 UTC+2 użytkownik Jacek Jędrzejewski napisał:

Still no.

JJ.

[Florian Gantier]

Yes, that's strange.

Either the load() function isn't called or $bTrigger isn't set to true, or maybe there is a file permission issue during the writing of log.html.

Can you test the file permissions by putting $bTrigger to true at the begin of load() function?

Florian

[Jacek Jędrzejewski]

I think we would better use log or upload directory ;) It's safer :)
Unfortunately right now I don't have the access to server's ftp so it
will have to wait :\

JJ.

2012/6/30 Florian Gantier <florian...@gmail.com>:

[Florian Gantier]

Ok, then you can test by adding the directory to the filename in the fopen.

Florian

Le 30/06/2012 11:05, Jacek J�drzejewski a �crit :

> I think we would better use log or upload directory ;) It's safer :)
> Unfortunately right now I don't have the access to server's ftp so it
> will have to wait :\
>
> JJ.
>
> 2012/6/30 Florian Gantier <florian...@gmail.com>:
>> Yes, that's strange.
>>
>> Either the load() function isn't called or $bTrigger isn't set to true, or
>> maybe there is a file permission issue during the writing of log.html.
>>
>> Can you test the file permissions by putting $bTrigger to true at the begin
>> of load() function?
>>
>> Florian
>>

>> Le 29/06/2012 16:20, Jacek J�drzejewski a �crit :

>>
>> It happened like 2 minutes ago, strange thing... But there is no log.html
>> file!
>>

>> W dniu pi�tek, 29 czerwca 2012 13:58:31 UTC+2 u�ytkownik Jacek J�drzejewski
>> napisaďż˝:
>>> Still no.
>>>
>>> JJ.
>>
>>

[TheCelavi]

Anyone tracking this one down? I have a same f*** issue.... And no clue why...

Thx and best,

TheCelavi

[Florian Gantier]

Well, I have given a kind a debugger to Jacek which normally should give
backtrace. It didn't work for him, and therefore I asked him to check
for directoy permissions which are necessary to write the file of the
backtrace.

He doesn't give news so far... Otherwise TheCelavi, you could as well
try, as I don't know myself very good how to trigger the error.

Florian

[TheCelavi]

OK. In order to reproduce the bug, we have to know how to trigger it.

Can someone just give me a steps to reproduce the bug?

[Kye Etherton]

Make the site inactive then open it while not logged in. 

Sent from my iPhone

[TheCelavi]

I know that - how to reproduce change of config in database, that is the issue... ?

[Florian Gantier]

In my precedents messages I have already explained where the possible sources (dmContext initialisation or sfConfig in load() function of dmConfig.php) of the problem could be tracked.

Otherwise change of config in database is due to the fact that when the get() member of dmConfig is called and that despite the loading of the configuration in DB, it doesn't find it, then it sets the searched config to default which is NULL.
With my debugger, my supposition is that the loading somehow fails.

As Jacek didn't get for the moment results with my debugger, it could be because the problem is different, but you should at least give it a try and if it fails, it would discard the origin of load() function and force to search somewhere else.

Florian

[Jacek Jędrzejewski]

I've experienced no problems with site inactive after applying that "language" fix so I have no backtrace.

JJ.

[Florian Gantier]

Ok, Jacek.

You had told before that you still had the problem even after the "language" fix. But if it is OK now, good.

Maybe TheCelavi should also try it, just in case, to see.

Florian

[Florian Gantier]

Otherwise does anyone knows if the problem occurs when APC is not activated?

Florian

[Florian Gantier]

Otherwise does anyone know if the problem occurs when APC is not activated?

Florian