AndyParsons...

Checked the UI to see the logs, saw 88F47313US535502H.

To Commandr...

Looking up transaction...

:var_dump($GLOBALS['SITE_DB']->query_select('transactions',array('*'),array('id'=>'88F47313US535502H')));:

array(1) {
[0]=>
array(12) {
["id"]=>
string(17) "88F47313US535502H"
["purchase_id"]=>
string(4) "1419"
["status"]=>
string(9) "Completed"
["reason"]=>
string(0) ""
["amount"]=>
string(5) "20.00"
["t_currency"]=>
string(3) "GBP"
["linked"]=>
string(2) "-1"
["t_time"]=>
int(1400506572)
["item"]=>
string(10) "USERGROUP5"
["pending_reason"]=>
string(0) ""
["t_memo"]=>
string(0) ""
["t_via"]=>
string(6) "paypal"
}
}

Looking up subscription for transaction...

:var_dump($GLOBALS['SITE_DB']->query_select('subscriptions',array('*'),array('id'=>1419)));:

array(1) {
[0]=>
array(10) {
["id"]=>
int(1419)
["s_type_code"]=>
string(10) "USERGROUP5"
["s_member_id"]=>
int(26495)
["s_state"]=>
string(6) "active"
["s_amount"]=>
string(2) "20"
["s_special"]=>
string(5) "26495"
["s_time"]=>
int(1368946980)
["s_auto_fund_source"]=>
string(6) "paypal"
["s_auto_fund_key"]=>
string(17) "88F47313US535502H"
["s_via"]=>
string(6) "paypal"
}
}

Looking up all subscriptions for user, in case there are conflicts...

:var_dump($GLOBALS['SITE_DB']->query_select('subscriptions',array('*'),array('s_member_id'=>26495)));:

array(2) {
[0]=>
array(10) {
["id"]=>
int(1419)
["s_type_code"]=>
string(10) "USERGROUP5"
["s_member_id"]=>
int(26495)
["s_state"]=>
string(6) "active"
["s_amount"]=>
string(2) "20"
["s_special"]=>
string(5) "26495"
["s_time"]=>
int(1368946980)
["s_auto_fund_source"]=>
string(6) "paypal"
["s_auto_fund_key"]=>
string(17) "88F47313US535502H"
["s_via"]=>
string(6) "paypal"
}
[1]=>
array(10) {
["id"]=>
int(2689)
["s_type_code"]=>
string(10) "USERGROUP5"
["s_member_id"]=>
int(26495)
["s_state"]=>
string(6) "active"
["s_amount"]=>
string(2) "20"
["s_special"]=>
string(0) ""
["s_time"]=>
int(1400540400)
["s_auto_fund_source"]=>
string(0) ""
["s_auto_fund_key"]=>
string(17) "manual-537da7a433"
["s_via"]=>
string(6) "manual"
}
}

(no conflicts)

Checking Apache logs...

173.0.81.1 - - [19/May/2014:08:36:12 -0500] "POST /data/ecommerce.php?from=paypal&product=USERGROUP5 HTTP/1.0" 200 - "-" "PayPal IPN ( https://www.paypal.com/ipn )"
173.0.81.1 - - [19/May/2014:08:36:53 -0500] "POST /data/ecommerce.php?from=paypal&product=USERGROUP5 HTTP/1.0" 200 - "-" "PayPal IPN ( https://www.paypal.com/ipn )"

Checked Composr error log, nothing relevant.

Checking e-mails...

:var_dump($GLOBALS['SITE_DB']->query_select('logged_mail_messages',array('*'),array('m_date_and_time'=>1400506572),'',1));:

array(1) {
[0]=>
array(18) {
["id"]=>
int(1582227)
["m_subject"]=>
string(35) "Notification: Subscription paid for"
["m_message"]=>
string(229) "This e-mail from The Mk1 Golf Owners Club was generated automatically and sent to you due to your notification settings. You should not reply directly.

---

A subscription, Become a Paid Member, has been paid for by AndyParsons."
["m_to_email"]=>
string(39) "a:1:{i:0;s:21:"[email protected]";}"
["m_to_name"]=>
string(19) "s:11:"lhasadreams";"
["m_from_email"]=>
string(0) ""
["m_from_name"]=>
string(0) ""
["m_priority"]=>
int(3)
["m_attachments"]=>
string(2) "N;"
["m_no_cc"]=>
int(0)
["m_as"]=>
int(1)
["m_as_admin"]=>
int(0)
["m_in_html"]=>
int(0)
["m_date_and_time"]=>
int(1400506572)
["m_member_id"]=>
int(1)
["m_url"]=>
string(84) "http://vwgolfmk1.org.uk/data/ecommerce.php?page=start&from=paypal&product=USERGROUP5"
["m_queued"]=>
int(0)
["m_template"]=>
string(4) "MAIL"
}
}

The code would only have sent that email in a branch where the user would be added to a group (it's sent right after that happens). For your site, it is the "$GLOBALS[(get_forum_type()=='cns')?'FORUM_DB':'SITE_DB']->query_update('f_members',array('m_primary_group'=>$new_group),array('id'=>$member_id),'',1);" line.

if ((get_value('unofficial_ecommerce')=='1') && (get_forum_type()!='cns'))
{
$GLOBALS['FORUM_DB']->add_member_to_group($member_id,$new_group);
} else
{
if ($myrow['s_uses_primary']==1)
{
$GLOBALS[(get_forum_type()=='cns')?'FORUM_DB':'SITE_DB']->query_update('f_members',array('m_primary_group'=>$new_group),array('id'=>$member_id),'',1);
} else
{
cns_add_member_to_group($member_id,$new_group);
}
}
dispatch_notification('paid_subscription_started',NULL/*strval($usergroup_subscription_id)*/,do_lang('PAID_SUBSCRIPTION_STARTED'),get_translated_text($myrow['s_mail_start'],NULL,get_lang($member_id)),array($member_id),A_FROM_SYSTEM_PRIVILEGED);


I did note that this is a cold case. The transaction here is one year after the subscription, i.e. auto-renewal:

(1400506572-1368946980)/60/60/24 = 365

As the first case I investigated is a cold case, I have added additional logging (not much more I can do)...

1) I've turned on the raw eCommerce log and protected it from HTTP downloads. data_custom/ecommerce.log
That said, I don't think this is an IPN issue, so don't expect to see much interesting in there.

2) I've added additional audit/action logging into Composr. For if the member's primary group is changed, or if they are added or deleted from any group.

For AndyParsons, I suspect that somebody edited his group memberships a long time back. This additional audit would help us tell for such a future case.

He hasn't done anything himself though since the auto-renewal, which happened on Monday 19th May, but he's not been online since the 10th May. This is odd, it suggests someone else edited his profile since the renewal happened.

I can't see anything else in the code that could change his group. The Paid member group doesn't have a rank that auto-promotes to another group, for example. That said, I did just check promotion logging...

:var_dump($GLOBALS['SITE_DB']->query_select('adminlogs',array('*'),array('param_b'=>'AndyParsons')));:

array(2) {
[0]=>
array(7) {
["id"]=>
int(15936)
["the_type"]=>
string(29) "MEMBER_PROMOTED_AUTOMATICALLY"
["param_a"]=>
string(5) "26495"
["param_b"]=>
string(11) "AndyParsons"
["the_user"]=>
int(26495)
["ip"]=>
string(14) "90.213.194.203"
["date_and_time"]=>
int(1369399172)
}
[1]=>
array(7) {
["id"]=>
int(19679)
["the_type"]=>
string(29) "MEMBER_PROMOTED_AUTOMATICALLY"
["param_a"]=>
string(5) "26495"
["param_b"]=>
string(11) "AndyParsons"
["the_user"]=>
int(26495)
["ip"]=>
string(14) "90.213.194.241"
["date_and_time"]=>
int(1385763919)
}
}

:echo get_timezoned_date(1369399172);:

24 May 2013, 1:39 PM

:echo get_timezoned_date(1368946980);:

19 May 2013, 8:03 AM

He did get promoted 5 days after. I think it was one of his secondary groups though, which is a rank-set group and has been promoted.

Running the same tests for hehelios I could see clearly the promotion email went out for him, so he was added, yet you say he was not there, hence he must have got removed somehow.

So I've grepped the code directly on your server, and analysed each case of group alteration...

Promotions:
./sources/cns_posts_action2.php: $GLOBALS['FORUM_DB']->query_update('f_members',array('m_primary_group'=>$_p),array('id'=>$member_id),'',1);
(impossible, no promotions logged for this member)

Editing member, changing primary group:
./sources/cns_members_action2.php: $update['m_primary_group']=$primary_group;
(impossible, member cannot edit own primary group, and no audit logged for someone else editing this member)

Deleting a group:
./sources/cns_groups_action2.php: $GLOBALS['FORUM_DB']->query_update('f_members',array('m_primary_group'=>$target_group),array('m_primary_group'=>$group_id));
(impossible, group was not deleted)

Subscription cancellation:
./sources/hooks/systems/ecommerce/usergroup.php: $GLOBALS[(get_forum_type()=='cns')?'FORUM_DB':'SITE_DB']->query_update('f_members',array('m_primary_group'=>get_first_default_group()),array('id'=>$member_id),'',1);
(impossible, no subscription cancellations for this member)

Subscription takeout:
./sources/hooks/systems/ecommerce/usergroup.php: $GLOBALS[(get_forum_type()=='cns')?'FORUM_DB':'SITE_DB']->query_update('f_members',array('m_primary_group'=>$new_group),array('id'=>$member_id),'',1);
(this is the code we want to run)

Group member timeouts, creating (i.e. switching them into a temporary usergroup):
./sources/group_member_timeouts.php: $GLOBALS[(get_forum_type()=='cns')?'FORUM_DB':'SITE_DB']->query_update('f_members',array('m_primary_group'=>$group_id),array('id'=>$member_id),'',1);
(you'd have known if you'd put them in a temporary usergroup)

Group member timeouts, expiring:
./sources/group_member_timeouts.php: $GLOBALS[(get_forum_type()=='cns')?'FORUM_DB':'SITE_DB']->query_update('f_members',array('m_primary_group'=>get_first_default_group()),array('id'=>$member_id),'',1);
(possible, if an expiring temporary usergroup was in the pipeline)

Warnings:
./site/pages/modules/warnings.php: $GLOBALS['FORUM_DB']->query_update('f_members',array('m_primary_group'=>$_changed_usergroup_from),array('id'=>$member_id),'',1);
(impossible, no warnings for this user)



So it may have been a case of there being a temporary usergroup that expired, after the PayPal transaction was performed, i.e. undoing it.
I can't verify this because the temporary usergroups (aka group member timeouts) are erased from the database when they finish.

I have added a line of code so that when a subscription activates a group change, it removes any group member timeouts sitting around for that member and usergroup combination.

Summary...

Probably we have two cases here.

One is the cold case of someone being removed accidentally, or perhaps via an old bug that I can't remember fixing for you.

The other is likely a temporary usergroup expiring after an ecommerce subscription was taken out. This is now mitigated as discussed in my last reply.

Thanks for working through this Chris.
Hopefully you have trapped it.
Will update this if it happens again.
I usually only find out when people complain - you would be amazed how many subscribe and then never complain that they do not have extended access !!
Cheers
Ade

Hi Chris,
Do you remember when you fixed something like this before and it regressed the functionality where when someone cancels their recurring PayPal it knocks them out of the paid members group ?
I have just got a user who has had this happen to them, username is TrialsRider. I have done a manual transaction to put it right.
Appreciate if you could take a look.
Cheers
Ade

We still had the old unfixed code in an override on your site, sorry about that.