Author Topic: Very frequent roster updates for guild bot running 0.6.4 (Read 2400 times)

Uragon · « **on:** August 01, 2009, 10:00:29 am »

I seem to be having an issue with roster updates for my AO guild bot after updating to version 0.6.4. The update itself (unpacked the 0.6.4 .tar.bz2 archive over the existing installation) went well, so did the restart. Three hours later though, the bot started doign roster updates every hour. Here's the log excerpts for the first three updates:

Quote

[06:10:13] [ROSTER] [UPDATE] Starting roster update for guild id: 206849 on RK1
[06:10:15] [ROSTER] [UPDATE] XML for the Omni guild Omni-Pol obtained
[06:10:15] [ROSTER] [UPDATE] XML for the Omni guild Omni-Pol contained 251 member entries
[06:10:48] [SETTINGS] [SAVED] LastRosterUpdate for module members set to 1249020648 as datatype int
[06:10:48] [ROSTER] [UPDATE] Roster update complete.
[06:10:48] [GROUP] [MSG] [Omni-Pol] Polbot: Roster update completed.
[09:10:16] [ROSTER] [UPDATE] Starting roster update for guild id: 206849 on RK1
[09:10:17] [ROSTER] [UPDATE] XML for the Omni guild Omni-Pol obtained
[09:10:17] [ROSTER] [UPDATE] XML for the Omni guild Omni-Pol contained 251 member entries
[09:10:55] [SETTINGS] [SAVED] LastRosterUpdate for module members set to 1249031455 as datatype int
[09:10:55] [ROSTER] [UPDATE] Roster update complete.
[09:10:55] [GROUP] [MSG] [Omni-Pol] Polbot: Roster update starting ::: System busy
[09:10:55] [GROUP] [MSG] [Omni-Pol] Polbot: Roster update completed.
[10:10:56] [ROSTER] [UPDATE] Starting roster update for guild id: 206849 on RK1
[10:10:58] [ROSTER] [UPDATE] XML for the Omni guild Omni-Pol obtained
[10:10:58] [ROSTER] [UPDATE] XML for the Omni guild Omni-Pol contained 251 member entries
[10:11:06] [SETTINGS] [SAVED] LastRosterUpdate for module members set to 1249035066 as datatype int
[10:11:06] [ROSTER] [UPDATE] Roster update complete.
[10:11:06] [GROUP] [MSG] [Omni-Pol] Polbot: Roster update starting ::: System busy
[10:11:06] [GROUP] [MSG] [Omni-Pol] Polbot: Roster update completed.

I'd assume it to be a problem with modules/Roster.php, as that seems to force the update hourly. Maybe this particular line doesn't produce the expected result in AO?

Code: [Select]

$buddies = $this -> bot -> aoc -> buddies;

Khalem · « **Reply #1 on:** August 01, 2009, 10:42:22 am »

$this->bot->aoc is AOChat, not Age of Conan in this context.

I'll look into this when i get a chance next week.

Uragon · « **Reply #2 on:** August 01, 2009, 11:10:16 am »

Ah, thanks for the feedback! As a temporary countermeasure, I've set the Buddylistupdate setting to 300 now. That should hopefully put a stop to the updates in the meantime.

Update: That did the trick. It seems my issue is that I've got people in the bot's buddy list that don't actually belong there. Currently 40 more in the buddy list than in the bot's notify list. I'm not really sure how they got there, maybe someone did an "!is" on them and they didn't get removed from the buddy list again. I'll poke the bot's logs after lunch, maybe I'll find out a bit more that will help debug this.

Post lunch update: The issue seems to be that buddies get added to the bot when either doing "!is <maincharacter>" for someone that has alts registered with the bot that aren't in the guild, or during a "!whois <randomcharacter>". Both operations add the character (in the case of !is all the alts listed) to the buddy list and don't remove it after the operation, or on a roster update. The buddy list of the bot grew from 291 to 301 characters over these last couple of hours.

Khalem · « **Reply #3 on:** August 02, 2009, 09:02:03 pm »

Nice catch.

Im betting this happened while someone fixed another issue related to !is or similar somewhere and this is the end result.

Either we need to clean out the buddylist after each time, or we need to separate the buddylist cleaning from the actual rosterupdate. And my initial thoughts are that the latter should happen regardles.

Khalem · « **Reply #4 on:** August 03, 2009, 10:54:09 pm »

Stumped.

I've been over the code which handles this, and cannot for the life of me find anything wrong nor can i reproduce it in any sane manner offhand.

Could you add the following debug code to 3 different locations in the code to try and help figure out where it goes wrong for you?

In Sources/Bot.php in the function inc_buddy around line 992 find

Code: [Select]

			if (!$mem)
			{
				$end = " (not on notify)";
				// Using aoc -> buddy_remove() here is an exception, all the checks in chat -> buddy_remove() aren't needed!
				$this -> aoc -> buddy_remove($user);
			}

Change to

Code: [Select]

			if (!$mem)
			{
				$end = " (not on notify)";
				// Using aoc -> buddy_remove() here is an exception, all the checks in chat -> buddy_remove() aren't needed!
				$buddies = $this -> aoc -> buddies;
				$buddy_count = count($buddies);
				$notify_db = $this -> db -> select("SELECT count(notify) FROM #___users WHERE notify = 1");
				$notify_count = $notify_db[0][0];
				echo "Debug: inc_buddy $user is not a member. Removing. Buddy count: $buddy_count | Notify count: $notify_count\n";
				$this -> aoc -> buddy_remove($user);
			}

in Sources/AOChat.php find around line 425

Code: [Select]

			case AOCP_BUDDY_REMOVE :
				unset($this->buddies[$packet->args[0]]);
				break;

Change to:

Code: [Select]

			case AOCP_BUDDY_REMOVE :
				$userid = $packet->args[0];
				unset($this->buddies[$packet->args[0]]);
				echo "Debug: $userid (" . $this->get_uname($userid) . ") successfully removed from buddylist\n";
				break;

And finally in modules/Roster.php find around line 325

Code: [Select]

	function cron()
	{
		$buddies = $this -> bot -> aoc -> buddies;
		$buddy_count = count($buddies);

		$notify_db = $this -> bot -> db -> select("SELECT count(notify) FROM #___users WHERE notify = 1");

		$notify_count = $notify_db[0][0];

		if ($notify_count - $buddy_count >= $this -> bot -> core("settings") -> get("Roster", "Buddylistupdate") || $buddy_count - $notify_count >= $this -> bot -> core("settings") -> get("Roster", "Buddylistupdate"))
		{
				$force = true;

				if ($this -> bot -> guildbot)
				{
					$this -> bot -> core("roster_core") -> update_guild($force);
				}
				else
				{
					$this -> bot -> core("roster_core") -> update_raid($force);
				}
		}
	}

Change to

Code: [Select]

	function cron()
	{
		$buddies = $this -> bot -> aoc -> buddies;
		$buddy_count = count($buddies);

		$notify_db = $this -> bot -> db -> select("SELECT count(notify) FROM #___users WHERE notify = 1");

		$notify_count = $notify_db[0][0];

		echo "Debug: Roster cron() called and counts $buddy_count buddies and $notify_count on notify list...";
		
		if ($notify_count - $buddy_count >= $this -> bot -> core("settings") -> get("Roster", "Buddylistupdate") || $buddy_count - $notify_count >= $this -> bot -> core("settings") -> get("Roster", "Buddylistupdate"))
		{
				echo " forcing roster update to fix\n";
				$force = true;

				if ($this -> bot -> guildbot)
				{
					$this -> bot -> core("roster_core") -> update_guild($force);
				}
				else
				{
					$this -> bot -> core("roster_core") -> update_raid($force);
				}
		}
		echo "\n";
	}

Uragon · « **Reply #5 on:** August 04, 2009, 02:21:46 pm »

I think I figured the problem out now. Those buddies aren't really in the bot's buddy list, it just thinks they are. It's related to recent changes in Source/AOChat.php's buddy_exists function.

Code: [Select]

$this->buddies[$uid] = 0;I'd assume this is intended to cache negative hits -- characters that aren't in the bot's buddy list. However, those verified non-buddies are also counted as buddies by Modules/Roster.php's list_buddies function:

Code: [Select]

foreach ($buddies as $id => $value)
{
        $buddy[$id] = $this -> bot -> core("chat") -> get_uname($id);
        $count++;
}

Khalem · « **Reply #6 on:** August 04, 2009, 06:50:46 pm »

Well done. That looks to be it.

This was actually my own doing as it was a fix for a PHP notice which wasn't thought trough properly as clearly evident by now

The fix is simple and has been committed to bzr.

Code: [Select]

	function buddy_exists($who)
	{
		if(($uid = $this->get_uid($who)) === false)
		{
			return false;
		}
		if (! isset($this->buddies[$uid]))
		{
			return 0;
		}
		return (int) $this->buddies[$uid];
	}