Anope Bug Tracker - Anope Development (1.9.x series)
View Issue Details
0001468Anope Development (1.9.x series)MemoServpublic2013-01-13 08:132013-01-25 10:33
CuttingEdge 
Adam 
normalminoralways
resolvedfixed 
Ubuntu Linux12.10
 
 
0001468: MemoServ displays 'new memo' notification twice when using MySQL database.
If 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.
1) Use MySQL database (instead of flatfile).
2) Send a new memo.
Using 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 [^]
No tags attached.
Issue History
2013-01-13 08:13CuttingEdgeNew Issue
2013-01-22 04:36AdamNote Added: 0006318
2013-01-22 04:36AdamAssigned To => Adam
2013-01-22 04:36AdamStatusnew => feedback
2013-01-23 07:56CuttingEdgeNote Added: 0006319
2013-01-23 07:56CuttingEdgeStatusfeedback => assigned
2013-01-23 10:00AdamNote Added: 0006320
2013-01-24 08:27CuttingEdgeNote Added: 0006321
2013-01-24 08:29CuttingEdgeNote Edited: 0006321bug_revision_view_page.php?bugnote_id=6321#r133
2013-01-24 08:46AdamNote Added: 0006322
2013-01-24 09:50CuttingEdgeNote Added: 0006323
2013-01-24 10:34CuttingEdgeNote Added: 0006324
2013-01-24 11:35CuttingEdgeNote Added: 0006325
2013-01-24 11:36CuttingEdgeNote Edited: 0006325bug_revision_view_page.php?bugnote_id=6325#r135
2013-01-24 13:09AdamNote Added: 0006326
2013-01-24 15:15CuttingEdgeNote Added: 0006327
2013-01-24 15:45AdamNote Added: 0006328
2013-01-25 10:33AdamNote Added: 0006329
2013-01-25 10:33AdamStatusassigned => resolved
2013-01-25 10:33AdamResolutionopen => fixed

Notes
(0006329)
Adam   
2013-01-25 10:33   
I believe this is fixed in 76d9e58ae59ca99452ebaeedef661d0f82fc7104. Repoen if you can still reproduce.
(0006328)
Adam   
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   
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   
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   
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   
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   
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   
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   
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   
2013-01-23 10:00   
Can you get the output of /ns glist on the target nick?
(0006319)
CuttingEdge   
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   
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`)