[role] token never interpreted (fixed, but needs test)

I'm unable to recreate this error, but I do appreciate your report.

Please let me know a few things:

1. Of these modules, which are enabled: token, token_actions, trigger.
2. Are you testing with the traditional settings at admin/user/role_change_notify, or are you using triggers and actions? If you're trying to use triggers, please make sure token_actions is enabled.
3. Please give a complete description of what you do, so I can recreate it. I need every detail: What you're trying to accomplish, how you configure it, what modules are enabled.

Thanks,
-Randy

I'm unable to duplicate this. Just tried it using your instructions.

I do appreciate the report.

I wonder why you'd be having such strange results. Are you using a dev version of anything?

It will be worth your time to try out a plain drupal install with just the requred modules and see what happens. As I mentioned in the other issue, I'm willing to look at a database dump.

Same issue here.

I tried [role], [rolename], [role-name].
None is replaced.

However, other token as [user], [site-xxx] stuff are.

@heltem, thanks for your report too. [role] is the correct token.

Please give complete information though:

Are you using the configuration at admin/user/role_change_notify to configure, or are you using triggers?
What modules do you have enabled? Token? Token Actions? Trigger?

Thanks to both of you for helping get this resolved. It appears that you have different problems.

@rfay : I use standard way to configure thru admin/user/role_change_notify and Token, Token Actions and Trigger are enabled.
From what I can see in module code, it seems the token_replace() call does not its job. As if it cannot find what it looks for in $account object (rolename property ?)

heltem, have you tried disabling modules to see if the behavior changes?

I'm certainly willing to look at a database dump to see if I can understand what's up with this.

Hi,

I went deeply into token module and it appears that we are on an unlucky way with token static runtime caching.
Indeed, before token module does its hook_token_values() call to retrieve all token to process, it does a check on passed object and type in order not to do twice such a call during the same page process.

And of course, it already did one with a similar object but without the role value. So it uses the cached token values and never replace the [role] token.
(See #262360: Expose control of token caching to functions that call token_replace)

It's probably due to another module which do a token_replace() call with a user object.

So here is a, probably not the best, way to fix it by flushing the token static runtime cache before the token_replace call in mail generation (See the provided patch)

Thanks, @heltem.

I also added a new token [role_changed] and made it the default in the message. It's far less likely to collide with another module.

Committed: http://drupal.org/cvs?commit=329972

This will be in the dev version on the next roll.
Please take a look at this and see if it resolves your issues.

I've made this "Active" again because I'm a new user of this module who's seeing problems like those already reported...

I'm using this with Triggers/Actions. I have all the relevant modules enabled. I'm also using role_delegation but the test below was done as the admin user.

I was trying to use the 2.0 version but both [role] and [role_changed] were replaced with an empty string in the email that was sent.

I switched to 2.x-dev (2010-03-11) and tried the following test by pasting the contents of the "User tokens" section from the "Placeholder tokens" help. The result in the email is this:

memtest	User's name
memtest	User's unfiltered name. WARNING - raw user input.
11	User's ID
test@example.com	User's email address
Fri, 02/11/2007 - 17:29	User's registration date
37 years 44 weeks	Days since the user registered
Fri, 12/03/2010 - 20:16	User's last login date
40 years 11 weeks	Days since the user's last login
Fri, 12/03/2010 - 20:45	The current date in the user's timezone
/users/memtest	The URL of the user's profile page.
/user/11/edit	The URL the user's account editing page.
[login_uri]	Login URL
[role]	Name of the role being added or removed
[role_changed]	Name of the role being added or removed

So, for some reason [login_uri], [role] and [role_change] don't get substituted but all the others do.

Any ideas?

Thanks...

peace & happiness,
martin

Hi Martin - thanks for the report. You're right that the dev version is the one to test this against.

Could you please post:
1. What other role-related modules you were using.
2. How you triggered the role change. (What did you do to change the role?)
3. The configuration of the action you were using, with the exact contents of the action's body or message field.
4. Whether you had token module enabled or not. (You can't do anything useful with actions unless you have token module enabled).

Thanks,
-Randy

Hi Randy,

Thanks for your reply!

1. Other role related modules:
   • CiviGroup Roles Sync - I'm using a recent SVN head due to PHP5.3 problems with the stable version. When a role is added to a user this module adds the contact corresponding to the user to a CiviCRM group.
   • Role Delegation 1.3.

   I disabled both of these modules and the tokens still weren't substituted. :-(

   I'm also using the Content Access module but it seems less likely to get in the way of something to do with role changes. It just uses the roles for ACLs. It is also not possible to disable it because I'll probably expose unwanted parts of my sites to the world.

   I also tried a 2nd site that I have that uses less modules. In particular it doesn't have CiviCRM (so no CiviGroup Roles Sync) or Role Delegation. Same problem.

2. I triggered the role change by, as the admin user, going to the user admin page (admin/user/user), selecting "Edit" next to the user, (de)selecting the relevant role and then hitting "Save".

   No use of role delegation here... or anything automatic... completely manual.

3. For the action configuration, none of Description/Recipient/Subject contain any tokens. The Message field contains this:

   [user]	User's name
   [user-raw]	User's unfiltered name. WARNING - raw user input.
   [uid]	User's ID
   [mail]	User's email address
   [reg-date]	User's registration date
   [reg-since]	Days since the user registered
   [log-date]	User's last login date
   [log-since]	Days since the user's last login
   [date-in-tz]	The current date in the user's timezone
   [account-url]	The URL of the user's profile page.
   [account-edit]	The URL the user's account editing page.
   [login_uri]	Login URL
   [role]	Name of the role being added or removed
   [role_changed]	Name of the role being added or removed
         

   and output in the email is:

   test	User's name
   test	User's unfiltered name. WARNING - raw user input.
   3	User's ID
   test@example.com	User's email address
   Sun, 2009-04-26 20:59	User's registration date
   39 years 17 weeks	Days since the user registered
   Mon, 2010-03-01 21:14	User's last login date
   40 years 9 weeks	Days since the user's last login
   Sat, 2010-03-13 10:54	The current date in the user's timezone
   /users/test	The URL of the user's profile page.
   /user/3/edit	The URL the user's account editing page.
   [login_uri]	Login URL
   [role]	Name of the role being added or removed
   [role_changed]	Name of the role being added or removed
         

   So all the tokens except login_uri/role/role_changed get substituted.

4. I'm using both Token and Token actions, version 1.12.

   The whole thing is running under Drupal 6.15 (with the rewrite-distinct patch from http://drupal.org/node/284392#comment-2389644, which should be in Drupal 6.16... when there's a Debian upgrade to it).

If you can point me at some vague places in the code, I can add some watchdog calls to log various things and see if I can work out what isn't happening.

The most likely place to start seems to be in token_actions.module in token_actions_send_email_action(). I should figure out how to dump the value of $context in various places near the top of the function. Should the tokens have values somewhere in $context? If that doesn't show the relevant tokens as having values then I should make sure that role_change_notify_token_values() is called and log something from there?

I take it that role_change_notify_user_update() is the hook that should get called by Drupal when roles are added/removed? Is the code I'm most interested in is _role_change_notify_trigger_actions()? I don't see that function doing anything with $role from role_change_notify_user_update() - should $role be passed between these functions and included in $token_info? Or should _role_change_notify_get_variables() be called somewhere here?

I think I'm missing something subtle...

Just checking my logic before spending a lot of time on it... If you have any other hints on how to approach debugging this then please let me know. I'm a competent programmer but I'm not familiar with all the moving parts here... :-)

peace & happiness,
martin

Hi Martin - In the current dev, there's no hook any more. It all happens from role_change_notify_user(). You'll find your way to where actions_do() is called. That's the place where the stuff gets sent on to the action.

If you do a
drupal_set_message(print_r(whatever, TRUE));

it makes for a decent debugging call. I think in D6 you can also just use debug();

Please note that I did a major overhaul on how this whole thing works just the other day, but as I remember you're using the current dev, so that should be OK. See #736086: Cannot use object of type stdClass as array, Remove extra hook invocation.

What happens is the $account variable gets $account->role_changed set on it.

I'm trying to move people from [role] (which seems to conflict with some other modules) to [role_changed], although both should be equivalent right now.

Thanks for your work on this.

-Randy

Hi Randy,

I think I see what's happening... but I don't understand why!

If I add some tracing to role_change_notify_token_values() and role_change_notify_user_update() - the latter in each loop just *before* the call to _role_change_notify_trigger_actions() - then I see the calls happen in this order:

# role_change_notify_token_values
# role_change_notify_user_update - remove

for both add and remove.

That doesn't make sense to me! I would have thought it would be the call to actions_do() that would eventually cause role_change_notify_token_values() to be called. It looks like the action is actually being invoked (and, hence, token values are being retrieved) before role_change_notify_user() is called, so the tokens don't get setup right... but I don't see how that can happen since role_change_notify is implementing the action! :-(

If I dump the value of $account then I see the expected problem: no value for $account->rolename in role_change_notify_token_values() so nothing much happens in that function. I see $account->rolename in role_change_notify_user_update() - I'd better, since it has just been set in each case.

Am I on the right track?

peace & happiness,
martin

martin, I just tried this on a clean Drupal6 install with the latest role_change_notify dev version, and had no trouble.

Using your input, below is what I got.

Please simplify your configuration and see what you can figure out. Go down to the bare minimum, uninstall all contrib modules but token, token actions, role_change_notify.

Also, I recommend testing with "tokenized system message" instead of "tokenized email". It's just easier to sort these things out.

Please make sure you're using the current dev release so we're comparing apples to apples.

newuser User's name
newuser User's unfiltered name. WARNING - raw user input.
3 User's ID
randy+newuser@randyfay.com User's email address
Wed, 03/03/2010 - 10:36 User's registration date
40 years 10 weeks Days since the user registered
Wed, 03/03/2010 - 10:36 User's last login date
40 years 10 weeks Days since the user's last login
Sat, 03/13/2010 - 13:12 The current date in the user's timezone
/user/3 The URL of the user's profile page.
/user/3/edit The URL the user's account editing page.
http://drupal6.l/user Login URL
administrator Name of the role being added or removed
administrator Name of the role being added or removed 

If I disable the pathauto module then the problem goes away. Interestingly, if I empty out the user path setting then the problem still happens - I thought that might work around things...

I'll keep digging.

Just in case anyone else is looking at this... :-)

Getting closer - I disable pathauto's hook_user by renaming pathauto_user() to pathauto_userx() then the problem goes away.

Got it!

pathinfo fills the static token cache too early in the whole process. As part of its work in pathinfo_user() it calls pathauto_get_placeholders(), which directly calls token_get_values() and this loads the cache. It almost does the right thing, passing $flush = TRUE. However, this doesn't flush the cache at the end of token_get_values().

So, by the time an action is invoked for role_change_notify, the call chain of token_actions_send_email_action(), token_replace_multiple(), token_get_values() doesn't actually cause role_change_notify_token_values() to be called. If I nobble the cache code in token_get_values() then the problem goes away.

This would cause problems for anyone using pathauto and other modules that implement hook_token_values(), depending on more order (and perhaps weights).

So this might not be a role_change_notify bug - it is probably a bug in either pathinfo or token.

However, it isn't clear how it should be fixed. It may have something to do with the module weights... but I don't know enough about that to be sure.

I'd argue that token_action should somehow do more cache flushing to avoid this if token_get_values() isn't considered a private function. Perhaps token_get_values() should cache per-module?

Randy, I'd be interested in your opinion before I report this as a bug somewhere else. You've got more experience with token(_actions)... :-)

peace & happiness,
martin

Shucks, that's the same thing that heltem figured out in #8 of this exact issue. But the token flush was put too late for you.

Please try this patch and see if it resolves this for you. Please test this one carefully, as I haven't recreated your situation.

@heltem: You mastered this the first time. Does this one look OK to you?

Wow, that's embarrassing. Sorry, I should have read right through the comments (and code) more carefully. I could have saved myself 2 or 3 hours if I'd read heltem's comment in any detail. Oh well, at least several of us now have a reasonable understanding of the token code... ;-)

A quick test shows that the patch fixes the add case but not the remove case. The remaining problem is pretty obvious: the cache flush (i.e. the same code) is also needed in the remove loop.

Yikes! That's a pretty high maintenance and expensive cache. :-( It would be much better if the token module provided a hook to invalidate just part of the cache... or something...

Well, I'm glad we solved that one... thanks for your help!

peace & happiness,
martin

Here I thought once again that I had put it once and for all in the right place.

Here's a reroll with the flush in the role removal as well.

Would much appreciate if you could test exhaustively, including testing the path where the traditional email path is used (with tokens) -- meaning not using actions, but just using the Role Change Notify interface (with tokens) at admin/user/role_change_notify. Not that it does not have a capacity for notification on role removal.

Yep, that all seems to work!

I tried adding/removing combinations of roles. I also tried combinations of triggers and the user notification emails.

Nice work! Thanks again...

peace & happiness,
martin

Committed to DRUPAL-6--2: http://drupal.org/cvs?commit=341358

I don't want to see this in the D7 version, so moving this issue there.

Thanks for the good work, Martin.

We need to verify that this behavior does not exist in the D7 branch. I just did a quick check and do not find anything in the new core tokens that allows us to flush the token cache.

@martin: Please post here exactly the module and configuration combination that got us into trouble on D6. I know you said it involved pathauto.

Hi,

Sorry @Martin.Schwenke, I missed the role_removed issue.

@rfay, what do you think about an unique factored flush call to token_get_values() outer the both foreach() loops ?

Here is my proposal.

Well, it seems I am late :-)

Here is the previous patch ported to match your commit to DRUPAL-6--2 (http://drupal.org/cvs?commit=341358)

Thanks, @heltem: Are you providing a D7 patch? There is no 'token' module in D7.

#23 is what I committed to D6. Isn't that the same as what you're saying?

Thanks so much for all your work on this.

Sorry for my confusing words.
It's a D6 patch to improve previous ones by doing the flush call outer the both foreach loops (role_added, role_removed).

I am not an early D7 player :-D so I can't port the D6 patch to D7.

@heltem, I think that's what I did in #23. Is it not?

@rfay, not exactly.

My #28 patch applies after yours and it moves the token_get_values(...) call before the both foreach() loops and make this call unique for the function.

@heltem, I agree. I was thinking we shouldn't clear the tokens out there because we didn't know whether we were going to need to, but in reality, we already know because of the test in role_change_notify_user().

#28: role_change_notify.token_flush_710210_28.patch queued for re-testing.

You're right, maybe we should test before if $rolesadded and $roles_removed are not empty.

What do you think about it ?

Hi heltem,

I don't understand how your latest patch works. I see that the call to token_get_values() passes NULL for $object. That seems to avoid priming the cache for 'user' tokens.

However, the 1st time the loop calls _role_change_notify_trigger_actions() will cause token_get_values() to be called for the 1st role. Won't that set the cache and get us stuck in a different way? Don't we need to clear the cache every time around the loop?

I haven't tested... but thought I'd ask the question before I did. What am I missing? :-)

Thanks...

peace & happiness,
martin

Hi Randy,

The problem was a combination of pathauto priming the cache and
role_change_notify not clearing the cache:

• pathauto calls token_get_values() in pathauto_user(). This ends
  up calling role_change_notify_token_values() before
  role_change_notify_user() has been called, so
  role_change_notify_token_values() doesn't know about the changed
  role. So, by calling token_get_values(), pathauto effectively
  primes the cache with tokens that aren't useful to
  role_change_notify.
• Due to the above, role_change_notify's call to actions_do()
  results in calls to token_get_values() and these calls only ever
  fetch from the cache, so role_change_notify_token_values() is
  never called at this point. Flushing the cache removes the
  incorrect token information and ensures that
  role_change_notify_token_values() is called after
  role_change_notify_user() has set things up.

There's no real configuration associated with this, except that when I
hit the problem it was only happening with the trigger option in
role_change_notify.

Modules other than pathauto might call token_get_values() directly and
cause a similar problem. However, I use over 20 common modules on my
main site and pathauto is the only culprit among those modules.

How's that?

peace & happiness,
martin

Hi Martin,

From my understanding, the issue does not come from the role value replacement but from the fact that [role], [role_changed] and others needed token are not known as token pattern to be replaced because of the incomplete cached token patterne list, not the cached token value list.

So, when token pattern list cache is flushed, it let the token pattern list to be refreshed with new token pattern known to be processed.
And one flush should be enough to get the new token pattern list.

I hope my explanation was clear enough :-)

Unfortunately the patch in comment #36 behaves as I expected. :-(

I setup a trigger to email notifications of role changes - the email contains [role_changed]. I then add 2 role "test1" and "test2" to a user "test". Both emails tell me that role "test1" has been added. However, the user admin screens clearly show that "test" now has both roles "test1" and "test2".

The caching code doesn't look as far down as individual tokens when it checks whether to use the cache:

  $id = _token_get_id($type, $object);
  if (isset($tokens[$type][$id])) {
    $tmp_tokens = $tokens[$type][$id];
  }
  else {
    $tmp_tokens = module_invoke_all('token_values', $type, $object, $options);
    $tokens[$type][$id] = $tmp_tokens;
  }

It just uses $type (which is 'user' in this case) and $id (which is the uid of the user), which are the same for each role change in the loop. :-(

So, I think we need to keep the cache flush inside the loop.

peace & happiness,
martin

Thanks for the excellent testing.

Now that you describe it, #36 isn't going to work right in the case of multiple role changes, either. If we add two roles, the second pass through the loop is going to get the cached token.

I'm going to call this fixed, and it's about time to do a release.

Both of you are outstanding community members and much appreciated.

BTW: I talked with davereid (token co-maintainer for D7) and he says there's no caching of this type to bite us in the D7 version.

Glad to have helped.... and thanks for being a responsive maintainer!

peace & happiness,
martin

Martin,

Great to see you tested beyond my actually-erroneous hypothesis.

Best regards,
heltem

On second thought, with as much pain as this has given us, this case needs a test. Probably a test that requires pathauto and that does a couple of role add/removes and verifies behavior. If either of you would be up for that, it's a great thing to have tests. I became a complete believer on this very module when the test I was writing caught a bug that already existed. There is a tutorial at http://drupal.org/node/395012 and it goes with the Examples module simpletest example. There are also existing tests for this. (Note that for D6 you have to remember to apply a patch to core or you get some strange failures.)

Sorry, I've had no time to work on this. Too much going on.

That said, 6.x-2.2 is now released, including the fixes for this bug, so should we just close this bug? Or keep it open for the dev version?

This issue is resolved, but remains open to remember to add tests.

Thanks! If you're interested in rolling a patch that includes a test, you are encouraged :-) There's a tutorial at http://drupal.org/simpletest-tutorial.