Internal: User key not found in session.

[nervino]

Hello, after the upgrade from 2.1.6 to 2.2.1 I get this error when trying to visit a frontend page that call a custom module:

Code: Select all

Error: at line 138 in file /var/www/derenzi/lib/classes/internal/class.LoginOperations.php:
Internal: User key not found in session.

It seems related to login but the page is public and there is no user/login check in the action.default.php file of my module.

Ideas?

Thanks.

[scooper]

Nothing helpful I'm afraid but I've had this a couple of times now as well.

When I've been logged into the admin area and then opened a page with a module in the same browser I've had the 'User key not found' error. Opening the page in a different browser (where I'm not logged in as admin) is absolutely fine and if I close the original browser and log in again it's also fine.

Not been able to reproduce it consistently of course. I suspect some kind of session problem so I'll fire up a couple of VMs and leave myself logged in to see if I can pin it down.

[nervino]

Thank you scooper.
Today the page is displaying right also when I'm logged in admin.
I agree with you, it must be some kind of session issue...

[calguy1000]

Please post precise steps to reproduce the problem from a clean installation.

[nervino]

I've made two tests but I couldn't reproduce the problem.

First test:
1) Installed 2.2.1
2) Installed custom module
3) Visited the page that calls custom module
All works fine

Second test (condition similar to the one in which problems had arisen):
1) Installed 2.1.6
2) Installed custom module
3) closed browser
4) opened browser
5) logged in cmsms admin
6) updated from 2.1.6 to 2.2.1
7) Visited the page that calls custom module
All works fine

[milehigh]

I actual came here to post the exact same thing on a 2.2.1 install.

Seems to be if I walk away from the browser then come back then I get that error message and I also concur that it seems to be on the browser that you are logged into the backend but that might be just because we are all managing the site so we're always logged into the backend.

If I do initiate a separate Firefox or IE session I don't get the error while it shows up in Chrome (I usually use Chrome).

The only thing different I've done on this install is that I am using Front End Users and Self-Registration. I rarely use those modules but the custom module I am using I've used for several years.

[scooper]

Had it again today myself. Was in the back end (and had been logged in for a long time) and when I opened a new tab to view my changes (custom module) the same error occurred:

Code: Select all

Sorry, it looks like something went wrong and an error has occurred.
Don’t worry, it can happen to any of us.
Error: at line 138 in file /var/sites/public_html/lib/classes/internal/class.LoginOperations.php:

Message:
Internal: User key not found in session.

I copied the 'full stack trace' as well if that's any help.

Sadly I've not been able to work out a way of repeating the error - mostly because most of the things I've tried so far involve leaving browsers logged in for 12 hours at a time to see if things time out. I'll keep trying though.

[calguy1000]

The problem occurs when the session times out... which usually takes inactivity of about ~15 minutes. Depending on server settings.

I checked the code, and the system is supposed to be copying cookie data (if it exists) into session data so that this issue does not occur.

But it seems it is related to a custom module, so it could still be anything. Some modules do strange stuff and may break due to some 'fix' in core functionality.

Does it happen with News? with any of the popular modules? Admin requests only?

[calguy1000]

BTW, please post the full stack trace. It may help.

[scooper]

Ahhh - getting there.

Just pasting in this full stack trace I noticed that lines 2-5 are an error for a bit of ropey SQL (hey I was tinkering). Sooo - I've just added a deliberately invalid SQL query to my custom module:

Code: Select all

$db->Execute("SELECT * FROM some_made_up_table;");

and indeed I get the 'User key not found in session' error in the browser where I'm logged in as admin. On a separate browser where I'm not logged in the error just gets ignored and the frontend page displays correctly.

So maybe debug_to_log() or something is doing things prior to the cookie data being loaded into the session?

Here's the stack trace anyway:

Code: Select all

Error: at line 138 in file /var/sites/public_html/lib/classes/internal/class.LoginOperations.php:

Message:

Internal: User key not found in session.

Close Full Trace ↑

#0 /var/sites/public_html/lib/page.functions.php(90): CMSMS\LoginOperations->validate_requestkey()
#1 /var/sites/public_html/lib/misc.functions.php(411): check_login(true)
#2 /var/sites/public_html/lib/classes/Database/class.compatibility.php(96): debug_to_log('Database Error:...')
#3 [internal function]: CMSMS\Database\compatibility::on_error(Object(CMSMS\Database\mysqli\Connection), 'EXECUTE', 1064, 'You have an err...')
#4 /var/sites/public_html/lib/classes/Database/class.Connection.php(675): call_user_func('\\CMSMS\\Database...', Object(CMSMS\Database\mysqli\Connection), 'EXECUTE', 1064, 'You have an err...')
#5 /var/sites/public_html/lib/classes/Database/mysqli/class.Connection.php(127): CMSMS\Database\Connection->OnError('EXECUTE', 1064, 'You have an err...')
#6 /var/sites/public_html/lib/classes/Database/class.Connection.php(328): CMSMS\Database\mysqli\Connection->do_sql('SELECT * FROM c...')
#7 /var/sites/public_html/lib/classes/Database/class.Connection.php(341): CMSMS\Database\Connection->SelectLimit('SELECT * FROM c...', -1, -1, NULL)
#8 /var/sites/public_html/modules/HashTrash/action.default.php(114): CMSMS\Database\Connection->Execute('SELECT * FROM c...')
#9 /var/sites/public_html/lib/classes/class.CMSModule.php(1415): include('/var/sites/h/hw...')
#10 /var/sites/public_html/lib/classes/class.CMSModule.php(1489): CMSModule->DoAction('default', 'm8e94b', Array, '18')
#11 /var/sites/public_html/lib/module.functions.php(106): CMSModule->DoActionBase('default', 'm8e94b', Array, '18', Object(Smarty_Internal_Template))
#12 /var/sites/public_html/lib/classes/class.CMSModule.php(270): cms_module_plugin(Array, Object(Smarty_Internal_Template))
#13 /var/sites/public_html/tmp/templates_c/e47747a9d075f96463f3d893a106f66f740181e5_0.tpl_body.23.php(66): CMSModule::function_plugin(Array, Object(Smarty_Internal_Template))
#14 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_runtime_inheritance.php(238): Block_1903278208595aad74d32366_47975590->callBlock(Object(Smarty_Internal_Template))
#15 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_runtime_inheritance.php(170): Smarty_Internal_Runtime_Inheritance->callBlock(Object(Block_1903278208595aad74d32366_47975590), Object(Smarty_Internal_Template))
#16 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_runtime_inheritance.php(172): Smarty_Internal_Runtime_Inheritance->process(Object(Smarty_Internal_Template), Object(Block_1903278208595aad74d32366_47975590), Object(Block_15931854055948f71ec189f9_42652596))
#17 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_runtime_inheritance.php(144): Smarty_Internal_Runtime_Inheritance->process(Object(Smarty_Internal_Template), Object(Block_15931854055948f71ec189f9_42652596))
#18 /var/sites/public_html/tmp/templates_c/b41f79ba0dba21d94888c9b86b3a8f0eeb03a109_0.cms_template.hwh3_core.php(114): Smarty_Internal_Runtime_Inheritance->instanceBlock(Object(Smarty_Internal_Template), 'Block_159318540...', 'main')
#19 /var/sites/public_html/lib/smarty/sysplugins/smarty_template_resource_base.php(128): content_5948f71ec1b406_75532666(Object(Smarty_Internal_Template))
#20 /var/sites/public_html/lib/smarty/sysplugins/smarty_template_compiled.php(172): Smarty_Template_Resource_Base->getRenderedTemplateCode(Object(Smarty_Internal_Template))
#21 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_template.php(206): Smarty_Template_Compiled->render(Object(Smarty_Internal_Template))
#22 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_template.php(372): Smarty_Internal_Template->render()
#23 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_runtime_inheritance.php(116): Smarty_Internal_Template->_subTemplateRender('cms_template:hw...', 'p18', NULL, 0, 3600, Array, 2, false, NULL, NULL)
#24 /var/sites/public_html/tmp/templates_c/e47747a9d075f96463f3d893a106f66f740181e5_0.tpl_body.23.php(32): Smarty_Internal_Runtime_Inheritance->endChild(Object(Smarty_Internal_Template), 'cms_template:hw...')
#25 /var/sites/public_html/lib/smarty/sysplugins/smarty_template_resource_base.php(128): content_595aad75099a36_57054523(Object(Smarty_Internal_Template))
#26 /var/sites/public_html/lib/smarty/sysplugins/smarty_template_compiled.php(172): Smarty_Template_Resource_Base->getRenderedTemplateCode(Object(Smarty_Internal_Template))
#27 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_template.php(206): Smarty_Template_Compiled->render(Object(Smarty_Internal_Template))
#28 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_templatebase.php(216): Smarty_Internal_Template->render(false, 0)
#29 /var/sites/public_html/lib/smarty/sysplugins/smarty_internal_templatebase.php(107): Smarty_Internal_TemplateBase->_execute(Object(Smarty_Internal_Template), NULL, NULL, NULL, 0)
#30 /var/sites/public_html/index.php(155): Smarty_Internal_TemplateBase->fetch()
#31 {main}

[scooper]

and following on from that I just had the error when using a template without a custom module one (just News and Search).

same error in the stack trace about trying to log an error (not mine this time).

Code: Select all

#2 /var/sites/xxxx/public_html/lib/classes/Database/class.compatibility.php(96): debug_to_log('Database Error:...')

I also notice that the changelog for 2.2.1 says

Code: Select all

Fix CMSSmartySecurityPolicy so that debug_to_log is no longer an allowed function.

so should we even be calling it? (certainly commenting it out in class.compatibility.php has stopped the error but hard to tell if it's done it permanently).

[calguy1000]

debug_to_log is no longer allowed in templates. The core can still call it.

It seems the problem you are having is due to SQL errors. The database error handler calls debug_to_log by default, and it appears that that will fail if your session has timed out.

[milehigh]

My stack trace didn't have any SQL errors...though I did see a reference in my module and in my stack trace about trying to return

$this->CreateParameter('action','default',$this->Lang('helpaction'));

but that entry for 'helpaction' did not exist in my lang folder.

I fixed that in my module but will need to wait for my sessions to time out to see if it did any good.

debug_to_log is no longer allowed in templates. The core can still call it.

It seems the problem you are having is due to SQL errors. The database error handler calls debug_to_log by default, and it appears that that will fail if your session has timed out.

[milehigh]

It seems that ANY type of error that shows up within a module in combination with an extended period of time after being logged into the admin will trigger this.

I've duplicated the issue on a separate page purposely passing a bad SQL statement. Here are the steps and it's pretty repeatable at this point.

1) Put bad logic in module on page.
2) Load page...it will load fine.
2) Login to admin
3) Go outside and play all day.
4) Load same page above...you will get Internal: User key not found.
5) Relogin to admin (actually...simply VISITING /admin will to it, I don't even have to log back in so writing the session data from the cookie still seems to work fine as Calguy described).
6) Page will load fine.

My flawed logic still exists in my module...but the page loaded just fine in step 6.