Anope Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0001468Anope Development (1.9.x series)MemoServpublic2013-01-13 08:132013-01-25 10:33
ReporterCuttingEdge 
Assigned ToAdam 
PrioritynormalSeverityminorReproducibilityalways
StatusresolvedResolutionfixed 
PlatformOSUbuntu LinuxOS Version12.10
Product Version 
Target VersionFixed in Version 
Summary0001468: MemoServ displays 'new memo' notification twice when using MySQL database.
DescriptionIf one sends a memo, when services is configured to use a MySQL database (no flatfile), the notification about a new memo is sent twice to the recepient:

-MemoServ- You have a new memo from CuttingEdge.
-MemoServ- Type /msg MemoServ READ 4 to read it.
-MemoServ- You have a new memo from CuttingEdge.
-MemoServ- Type /msg MemoServ READ 4 to read it.
Steps To Reproduce1) Use MySQL database (instead of flatfile).
2) Send a new memo.
Additional InformationUsing MySQL database backend on latest Anope 1.9.x.

This may be related to this forum post:
http://forum.anope.org/index.php?topic=3898.0 [^]
TagsNo tags attached.
Attached Files

- Relationships

-  Notes
(0006329)
Adam (administrator)
2013-01-25 10:33

I believe this is fixed in 76d9e58ae59ca99452ebaeedef661d0f82fc7104. Repoen if you can still reproduce.
(0006328)
Adam (administrator)
2013-01-24 15:45

Oh, actually the documentation is right, I wasn't remembering correctly.

Try loading *just* db_flatfile and db_sql to do the initial import, then shutting down and going to *just* db_sql_live.

I'm trying to reproduce this now using the steps you gave and it appears okay.

If you could come to irc.anope.org/#anope sometime I could assist you in debugging this.
(0006327)
CuttingEdge (reporter)
2013-01-24 15:15

In the documentation (in services.conf) it says:

"This module should not be loaded in conjunction with db_sql, except during the initial import of existing databases to SQL."

Thats the only time I use them both. Once everything is imported over, I only run the db_sql_live module (not even the db_flatfile one).

If I only use the db_sql_live with db_flatfile initially, it doesn't create any tables in the database whatsoever. Is this correct? Is the order or sequence I'm loading them in, affecting this? The db_flatfile module is loaded before the db_sql_live one.
(0006326)
Adam (administrator)
2013-01-24 13:09

Your step 5:

5) Enabled the db_flatfile, db_sql and db_sql_live modules in services.conf.

You aren't supposed to load both db_sql and db_sql_live at one time. I'm not sure what happens when you do (I should probably make them fail to load if the other is loaded).

Can you reproduce it by only loading db_sql_live and not db_sql?
(0006325)
CuttingEdge (reporter)
2013-01-24 11:35
edited on: 2013-01-24 11:36

Some logs that I think are relative:

[Jan 24 11:21:21 2013] m_mysql: Fetching columns for Memo
[Jan 24 11:21:21 2013] m_mysql: Column #0 for Memo: id
[Jan 24 11:21:21 2013] m_mysql: Column 0000001 for Memo: timestamp
[Jan 24 11:21:21 2013] m_mysql: Column 0000002 for Memo: flags
[Jan 24 11:21:21 2013] m_mysql: Column 0000003 for Memo: owner
[Jan 24 11:21:21 2013] m_mysql: Column 0000004 for Memo: sender
[Jan 24 11:21:21 2013] m_mysql: Column 0000005 for Memo: text
[Jan 24 11:21:21 2013] m_mysql: Column 0000006 for Memo: time
[Jan 24 11:21:21 2013] SQL-live got 0 rows for INSERT INTO `Memo` (`id`,`flags`,`owner`,`sender`,`text`,`time`) VALUES (5958,'MF_UNREAD','','CuttingEdge','moo','1359018859') ON DUPLICATE KEY UPDATE `flags`=VALUES(`flags`),`owner`=VALUES(`owner`),`sender`=VALUES(`sender`),`text`=VALUES(`text`),`time`=VALUES(`time`)
[Jan 24 11:21:21 2013] Sent: :1SVAAAAAB FMODE #atrum-services 1359019279 +vvvvvvvr 1SVAAAAAA 1SVAAAAAB 1SVAAAAAC 1SVAAAAAD 1SVAAAAAE 1SVAAAAAF 1SVAAAAAG
[Jan 24 11:24:28 2013] Received: :9ZAAAAAFV PRIVMSG 1SVAAAAAE :list
[Jan 24 11:24:28 2013] SQL-live got 3 rows for SELECT * FROM `BotInfo` WHERE (`timestamp` > FROM_UNIXTIME(1359019280) OR `timestamp` IS NULL)
[Jan 24 11:24:28 2013] SQL-live got 0 rows for SELECT * FROM `NickCore` WHERE (`timestamp` > FROM_UNIXTIME(1359019280) OR `timestamp` IS NULL)
[Jan 24 11:24:28 2013] SQL-live got 1 rows for SELECT * FROM `Memo` WHERE (`timestamp` > FROM_UNIXTIME(1359019280) OR `timestamp` IS NULL)
[Jan 24 11:24:28 2013] SQL-live got 0 rows for SELECT * FROM `NickAlias` WHERE (`timestamp` > FROM_UNIXTIME(1359019280) OR `timestamp` IS NULL)
[Jan 24 11:24:29 2013] SQL-live got 0 rows for DELETE FROM `Memo` WHERE `id` = 5958

After this point, services splits and the process dies. Bare in mind, that my nickname still shows twice in '/nickserv glist'.

EDIT: To successfully reproduce this crash (every time), I have to send myself a memo, stop services, restart it and do a '/memoserv list'.

(0006324)
CuttingEdge (reporter)
2013-01-24 10:34

Something else to note, is that after restarting services a second time (after the memo's were cleared, and services crashed), given enough time, the same set of events occur (services clears out the memos), but this time round, doesn't crash and becomes completely unresponsive instead.

Services eventually splits, with a timeout. The actual process is still running - I have to terminate it by hand in order to restart it.
(0006323)
CuttingEdge (reporter)
2013-01-24 09:50

Redid the database from scratch, from a copy of the LIVE database, and ran into the same issue.

Followed the following procedure:

1) Shutdown the TEST set of services.
2) Dropped the database completely from MySQL.
3) Recreated a blank database.
4) Copied the anope.db file from the LIVE network.
5) Enabled the db_flatfile, db_sql and db_sql_live modules in services.conf.
6) Restarted the TEST set of services.
7) Gave Anope time to completely finish creating tables and copying the data over to MySQL.
8) Shutdown the TEST set of services.
9) Commented out the db_flatfile and db_sql modules from services.conf.
10) Restarted the TEST set of services.
11) Noticed that services runs through all the memos, then proceeds to delete them all.
12) Services crashes with no error after the last memo is deleted.
13) Confirmed that the Memo table is now empty.
14) Restarted the TEST set of services.
15) Confirmed that there were no memo's available for my user (/memoserv list).
16) Sent myself a memo - received the confirmation twice (as before).
17) Confirmed my nickname as being listed twice in /nickserv glist.

Hope this helps. The database on every occation hasn't been altered or manipulated externally.
(0006322)
Adam (administrator)
2013-01-24 08:46

I think it is more likely you edited the database externally and messed up something.

If you can reproduce it using Anope and nothing external that would be the real bug.
(0006321)
CuttingEdge (reporter)
2013-01-24 08:27
edited on: 2013-01-24 08:29

I think you hit the nail on the head.

It looks like CuttingEdge is listed twice in the GLIST output from NickServ. Not too sure how that happened. May have been from the initial MySQL importation perhaps?

EDIT: On the non-MySQL version of Anope, there only appears one. (I have two concurrent versions running - one for the live network, the other (MySQL) for test).

(0006320)
Adam (administrator)
2013-01-23 10:00

Can you get the output of /ns glist on the target nick?
(0006319)
CuttingEdge (reporter)
2013-01-23 07:56

[Jan 23 07:55:13 2013] Received: :9ZAAAAAFR PRIVMSG 1SVAAAAAE :send CuttingEdge moo
[Jan 23 07:55:13 2013] SQL-live got 0 rows for SELECT * FROM `BotInfo` WHERE (`timestamp` > FROM_UNIXTIME(1358920461) OR `timestamp` IS NULL)
[Jan 23 07:55:13 2013] SQL-live got 0 rows for SELECT * FROM `NickCore` WHERE (`timestamp` > FROM_UNIXTIME(1358920481) OR `timestamp` IS NULL)
[Jan 23 07:55:13 2013] SQL-live got 0 rows for SELECT * FROM `NickAlias` WHERE (`timestamp` > FROM_UNIXTIME(1358920481) OR `timestamp` IS NULL)
[Jan 23 07:55:13 2013] SQL-live got 0 rows for SELECT * FROM `Memo` WHERE (`timestamp` > FROM_UNIXTIME(1358920460) OR `timestamp` IS NULL)
[Jan 23 07:55:13 2013] Sent: :1SVAAAAAE NOTICE 9ZAAAAAFR :You have a new memo from CuttingEdge.
[Jan 23 07:55:13 2013] Sent: :1SVAAAAAE NOTICE 9ZAAAAAFR :Type /msg MemoServ READ 5 to read it.
[Jan 23 07:55:13 2013] Sent: :1SVAAAAAE NOTICE 9ZAAAAAFR :You have a new memo from CuttingEdge.
[Jan 23 07:55:13 2013] Sent: :1SVAAAAAE NOTICE 9ZAAAAAFR :Type /msg MemoServ READ 5 to read it.
[Jan 23 07:55:13 2013] Sent: :1SVAAAAAE NOTICE 9ZAAAAAFR :Memo sent to CuttingEdge.
[Jan 23 07:55:13 2013] SQL-live got 0 rows for INSERT INTO `Memo` (`id`,`flags`,`owner`,`sender`,`text`,`time`) VALUES (0,'MF_UNREAD','CuttingEdge','CuttingEdge','moo','1358920513') ON DUPLICATE KEY UPDATE `flags`=VALUES(`flags`),`owner`=VALUES(`owner`),`sender`=VALUES(`sender`),`text`=VALUES(`text`),`time`=VALUES(`time`)
[Jan 23 07:55:13 2013] Successfully delivered mail for CuttingEdge (cuttingedge@atrum.org)
[Jan 23 07:55:13 2013] Sent: :1SVAAAAAC PRIVMSG #atrum-services :Successfully delivered mail for CuttingEdge (cuttingedge@atrum.org)
(0006318)
Adam (administrator)
2013-01-22 04:36

Can you get debug logs of this? I'm unable to reproduce:

[Jan 21 21:35:31.499936 2013] Debug: Received: :Adam PRIVMSG MemoServ@services.rizon.net :send adam- moo
[Jan 21 21:35:31.500576 2013] Debug: SQL-live got 0 rows for SELECT * FROM `anope_db_BotInfo` WHERE (`timestamp` > FROM_UNIXTIME(1358822127) OR `timestamp` IS NULL)
[Jan 21 21:35:31.501032 2013] Debug: SQL-live got 0 rows for SELECT * FROM `anope_db_NickCore` WHERE (`timestamp` > FROM_UNIXTIME(1358822127) OR `timestamp` IS NULL)
[Jan 21 21:35:31.501513 2013] Debug: SQL-live got 0 rows for SELECT * FROM `anope_db_NickAlias` WHERE (`timestamp` > FROM_UNIXTIME(1358822127) OR `timestamp` IS NULL)
[Jan 21 21:35:31.501943 2013] Debug: SQL-live got 0 rows for SELECT * FROM `anope_db_Memo` WHERE (`timestamp` > FROM_UNIXTIME(1358821567) OR `timestamp` IS NULL)
[Jan 21 21:35:31.502140 2013] Debug: Sent: :00AAAAAAE NOTICE 00CAAAAAB :You have a new memo from Adam.
[Jan 21 21:35:31.502206 2013] Debug: Sent: :00AAAAAAE NOTICE 00CAAAAAB :Type /msg MemoServ READ 1 to read it.
[Jan 21 21:35:31.502360 2013] Debug: Sent: :00AAAAAAE NOTICE 00CAAAAAA :Memo sent to adam-.
[Jan 21 21:35:31.503257 2013] Debug: SQL-live got 0 rows for INSERT INTO `anope_db_Memo` (`id`,`flags`,`owner`,`sender`,`text`,`time`) VALUES (0,'MF_UNREAD','adam-','Adam','moo','1358822131') ON DUPLICATE KEY UPDATE `flags`=VALUES(`flags`),`owner`=VALUES(`owner`),`sender`=VALUES(`sender`),`text`=VALUES(`text`),`time`=VALUES(`time`)

- Issue History
Date Modified Username Field Change
2013-01-13 08:13 CuttingEdge New Issue
2013-01-22 04:36 Adam Note Added: 0006318
2013-01-22 04:36 Adam Assigned To => Adam
2013-01-22 04:36 Adam Status new => feedback
2013-01-23 07:56 CuttingEdge Note Added: 0006319
2013-01-23 07:56 CuttingEdge Status feedback => assigned
2013-01-23 10:00 Adam Note Added: 0006320
2013-01-24 08:27 CuttingEdge Note Added: 0006321
2013-01-24 08:29 CuttingEdge Note Edited: 0006321 View Revisions
2013-01-24 08:46 Adam Note Added: 0006322
2013-01-24 09:50 CuttingEdge Note Added: 0006323
2013-01-24 10:34 CuttingEdge Note Added: 0006324
2013-01-24 11:35 CuttingEdge Note Added: 0006325
2013-01-24 11:36 CuttingEdge Note Edited: 0006325 View Revisions
2013-01-24 13:09 Adam Note Added: 0006326
2013-01-24 15:15 CuttingEdge Note Added: 0006327
2013-01-24 15:45 Adam Note Added: 0006328
2013-01-25 10:33 Adam Note Added: 0006329
2013-01-25 10:33 Adam Status assigned => resolved
2013-01-25 10:33 Adam Resolution open => fixed


Copyright © 2000 - 2019 MantisBT Team
Powered by Mantis Bugtracker