Spurious error on duplicate keys with admin sync

[agouaux]

I didn't know if this was something separate from #7 or something different. #7 deals with editing the admins (owners and/or editors). However, this problem has to do with syncing these admins from a datasource. I'm going to attached an excerpt of the log regarding such a sync. The lines with "AAG" are additional log statements I inserted in an attempt to get more information about this. One thing that's frustrating is that I have not been able to replicate this behavior on the test system, despite them having the same sympa version, same perl version, same module versions (at least mostly.)

In the attached log excerpt, the list "ecs.bmen.staff" includes the list "etech" as owners.

etech-sympa-log.txt

[ikedas]

agouaux.

Could you please explain what you expected and how the result was unexpected?

As far as I understood: Owners have already been registered in admin_table, and thanks to primary-key constraint of the table, duplicate registrations were avoided.

[racke]

I think that this is caused by the stupid caching of admins and friends in 6.2.

[agouaux]

I upgraded to 6.2.18, but the problem persists.

Here's an example. List is called ecs.ee.allfac, and it includes the list etech for both the admins and editors. That has been working fine for a long time. However, after going to 6.2, now whenever I edit the List Definition, I get the following error message:

User amos@x.org has encountered an internal server error
(Web interface - ACTION: Command process - LIST:
ecs.ee.allfac@lists.x.org):

Failed to include list admins for list 'ecs.ee.allfac'

See the logs for more details.

along with this nasty error message on the screen:

So I agree that on one hand it is a non-serious error since it is just trying to add a duplicate entry, but:

• Either it needs to treat it as a non-serious error, or
• Add logic to determine if in fact those entries are already there and do not attempt to add duplicates.

Here's the log for when this occurs.

sympa.log.txt

[agouaux]

Here's the list config, if that matters:

owner_include
profile privileged
reception mail
source owner_or_moderator_sympa_list
visibility conceal
source_parameters etech

editor_include
reception mail
source owner_or_moderator_sympa_list
visibility conceal
source_parameters etech

and here's SYMPA_HOME/etc/data_sources/owner_or_moderator_sympa_list.incl

include_sympa_list
listname [%param.0%]
name owner_or_moderator_sympa_list

[agouaux]

I guess nobody has been able to reproduce this error? We're still routinely getting the errors that are shown in the log excerpt attached to the original comment....

[racke]

I got a similar error recently on a new Sympa 6.2.18 setup. I suppose we need to find the place in the code where it submits the list definition update and clear the cache before that.

[agouaux]

I'm trying to understand... how is it a cache issue? It is as if the code is trying to add all the owners included from another source as owners, when in fact they were already added as owners. That behavior doesn't sound like something that is caching, but rather something that is not remembering. It's as if it is not double-checking that those included owners are not already added before attempting to add them again. Anyway, despite wanting to dig into the code to learn for myself what's going on, I just haven't had the time to do so. Consequently, I'm just totally guessing here....

…

On Sun, Sep 10, 2017 at 8:56 AM, Stefan Hornburg (Racke) < ***@***.***> wrote: I got a similar error recently on a new Sympa 6.2.18 setup. I suppose we need to find the place in the code where it submits the list definition update and clear the cache before that. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#11 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AaGNNfBPbD4McasOFODgL18IDGqG2Y0aks5sg-qIgaJpZM4NEr6m> .

[ikedas]

Milestone means that we will try to solve this issue in this year. Helps are appreciated!

[ikedas]

Please check 6.2.23b.2

Note: This bug looks related with issue #7.

[ikedas]

If problem will not be reported reproducing by 14 Dec., I'll close this issue.

[agouaux]

Unfortunately, problem persists:

[root@aistsympa01 ~]# grep VERSION /deploy/sympa/bin/Sympa/Constants.pm
use constant VERSION => '6.2.23b.2';
[root@aistsympa01 ~]# cmp /deploy/www/wwsympa.fcgi /deploy/sympa/bin/wwsympa.fcgi

The stest1 list includes owners and editors from other lists:

owner_include
profile privileged
reception mail
source owner_or_moderator_sympa_list
visibility noconceal
source_parameters stest1editors

owner_include
source owner_or_moderator_sympa_list
reception nomail
profile privileged
visibility noconceal
source_parameters oit-sympa-admins

editor_include
reception mail
source owner_or_moderator_sympa_list
visibility noconceal
source_parameters stest1editors

editor_include
source owner_or_moderator_sympa_list
reception nomail
visibility noconceal
source_parameters oit-sympa-admins

and etc/data_sources/owner_or_moderator_sympa_list.incl includes the following:

include_sympa_list
listname [%param.0%]
name owner_or_moderator_sympa_list

sympa-log-err.txt

[ikedas]

@agouaux,

• Could you please show what operations you performed?
• Do you still see "Failed to include list admins" error or not?
• Is synchronization really failed (if some owners actually were not included into target list, it failed. otherwise it did not fail)?

[agouaux]

I get this in the web interface when I attempt to add the same address as both an owner and a moderator. This is pretty consistently repeatable.

and this is the error message that listmaster receives:

User user1@zzz.org has encountered an internal server error
(Web interface - ACTION: Command process - LIST: stest1@tlists.zzz.org):

Failed to include list admins for list 'stest1'

See the logs for more details.

The new address seems to be added to both owner and moderator despite the warning screen popup and the alert to listmaster.

If I add a new address as just owner, I get the error in the log about duplicate address being added (from the included lists), but no error in the GUI, and no error to list master.

No error if delete same address from both owner and moderator.

Sometimes, if address "a" is listed as an owner already (an Update previously done), then I add address "a" as a moderator, I get the error popup in the GUI and the alert to the listmaster. Though, once again if I subsequently check the list config, it appears the update was registered nonetheless. This doesn't happen all the time, but sometimes.

Whenever the sync update for the included lists for owner and moderator runs, I get the duplicate errors in the logs. If I have a number of lists configured this way, it results in a lot of errors in the logs, and probably a lot of needless chatter to the db server because it is trying to add addresses to either owner or moderator that are already listed in the db. It's as if it's not doing a query first before trying to add, but simply trying to add all the time those syncs are preformed.

[ikedas]

@agouaux, thanks for detailed report!

Spurious error messages are problem, however I look it a bit difficult to fix right away. So I think this issue would be kept open and would be fixed in the near future (next spring or ahead). Until then, please be patient ignoring the error messages.

[agouaux]

can someone please explain the intent of this logic:

# Update inclusion_table: This feature was added on 6.2.16.
sub _update_inclusion_table {
    my $self      = shift;
    my $role      = shift;
    my @depend_on = @_;
    $log->syslog('notice', "[AAG] self->get_id: $self->get_id; role: $role; \@depend_on: \"@depend_on\"");

    my $sdm = Sympa::DatabaseManager->instance;
    my $sth;

    my $now = time;
    foreach my $list_id (@depend_on) {
        $log->syslog('notice', "[AAG] list_id: $list_id ... do UPDATE, and if that fails, INSERT INTO ....");
        unless (
            $sdm
            and $sth = $sdm->do_prepared_query(
                q{UPDATE inclusion_table
                  SET update_epoch_inclusion = ?
                  WHERE target_inclusion = ? AND
                        role_inclusion = ? AND
                        source_inclusion = ? AND
                        (update_epoch_inclusion IS NULL OR
                         update_epoch_inclusion < ?)},
                $now, $self->get_id, $role, $list_id, $now
            )
            and $sth->rows
            or $sdm and $sth = $sdm->do_prepared_query(
                q{INSERT INTO inclusion_table
                  (target_inclusion, role_inclusion, source_inclusion,
                   update_epoch_inclusion)
                  VALUES (?, ?, ?, ?)},
                $self->get_id, $role, $list_id, $now
            )
            and $sth->rows
            ) {
            $log->syslog('err', 'Unable to update list %s in database',
                $self);
            return undef;
        }
    }
    $sdm->do_prepared_query(
        q{DELETE FROM inclusion_table
          WHERE target_inclusion = ? AND role_inclusion = ? AND
                update_epoch_inclusion < ?},
        $self->get_id, $role, $now
    );
}

I added more logging statements, and it seems like this may not be doing quite what folks are intending....

Dec 15 15:16:20 aistsympa01 wwsympa[110767]: notice Sympa::List::sync_include_admin() [AAG]    call _update_inclusion_table, role: owner; @depend_on: "oit-sympa-admins@tlists.zzz.org stest1editors@tlists.zzz.org"
Dec 15 15:16:20 aistsympa01 wwsympa[110767]: notice Sympa::List::_update_inclusion_table() [AAG] self->get_id: Sympa::List=HASH(0x5f362e0)->get_id; role: owner; @depend_on: "oit-sympa-admins@tlists.zzz.org stest1editors@tlists.zzz.org"
Dec 15 15:16:20 aistsympa01 wwsympa[110767]: notice Sympa::List::_update_inclusion_table() [AAG] list_id: oit-sympa-admins@tlists.zzz.org ... do UPDATE, and if that fails, INSERT INTO ....
Dec 15 15:16:20 aistsympa01 wwsympa[110767]: notice Sympa::Database::do_prepared_query() [AAG]  QUERY: "UPDATE inclusion_table SET update_epoch_inclusion = ? WHERE target_inclusion = ? AND role_inclusion = ? AND source_inclusion = ? AND (update_epoch_inclusion IS NULL OR update_epoch_inclusion < ?)";  PARAMS: "1513372580 stest1@tlists.zzz.org owner oit-sympa-admins@tlists.zzz.org 1513372580"
Dec 15 15:16:20 aistsympa01 wwsympa[110767]: notice Sympa::Database::do_prepared_query() [AAG]  QUERY: "INSERT INTO inclusion_table (target_inclusion, role_inclusion, source_inclusion, update_epoch_inclusion) VALUES (?, ?, ?, ?)";  PARAMS: "stest1@tlists.zzz.org owner oit-sympa-admins@tlists.zzz.org 1513372580"
Dec 15 15:16:20 aistsympa01 wwsympa[110767]: err main::#1606 > main::do_edit_list#10590 > Sympa::List::sync_include_admin#7010 > Sympa::List::_update_inclusion_table#6889 > Sympa::Database::do_prepared_query#383 Unable to execute SQL statement "INSERT INTO inclusion_table (target_inclusion, role_inclusion, source_inclusion, update_epoch_inclusion) VALUES (?, ?, ?, ?)": (23000) Duplicate entry 'oit-sympa-admins@tlists.zzz.org-owner-stest1@tlists.utdalla' for key 'PRIMARY'
Dec 15 15:16:20 aistsympa01 wwsympa[110767]: err main::#1606 > main::do_edit_list#10590 > Sympa::List::sync_include_admin#7010 > Sympa::List::_update_inclusion_table#6911 Unable to update list Sympa::List <stest1@tlists.zzz.org> in database

[agouaux]

This seems to work better for updating the inclusion table. Though, not sure what triggers the DELETE to occur.... (OK, the DELETE is to cleanup entries that should no longer be there.)

I've tested this minor change a bunch, and it seems to eliminate the error associated when updating the inclusion table.

The other error--adding the same address as owner and editor at once--I'm wondering if it could be something as simple as a COMMIT not being done after an INSERT or UPDATE.....

# Update inclusion_table: This feature was added on 6.2.16.
sub _update_inclusion_table {
    my $self      = shift;
    my $role      = shift;
    my @depend_on = @_;

    my $sdm = Sympa::DatabaseManager->instance;
    my $sth;

    my $now = time;
    foreach my $list_id (@depend_on) {
        $log->syslog('notice', "list_id: $list_id ... do UPDATE....");
        unless (
            $sdm
            and $sth = $sdm->do_prepared_query(
                q{UPDATE inclusion_table
                  SET update_epoch_inclusion = ?
                  WHERE target_inclusion = ? AND
                        role_inclusion = ? AND
                        source_inclusion = ? AND
                        (update_epoch_inclusion IS NULL OR
                         update_epoch_inclusion < ?)},
                $now, $self->get_id, $role, $list_id, $now
                )
            ) {
            $log->syslog('notice', "list_id: $list_id ... UPDATE failed, so do INSERT INTO ....");
            unless (
                $sdm and $sth = $sdm->do_prepared_query(
                q{INSERT INTO inclusion_table
                  (target_inclusion, role_inclusion, source_inclusion,
                   update_epoch_inclusion)
                   VALUES (?, ?, ?, ?)},
                    $self->get_id, $role, $list_id, $now
                )
                and $sth->rows
                ) {
                    $log->syslog('err', 'Unable to update list %s in database', $self);
                    return undef;
            }
        }
    }
    $log->syslog('notice', "self->get_id: $self->get_id; role: $role ... do DELETE ....");
    $sdm->do_prepared_query(
        q{DELETE FROM inclusion_table
          WHERE target_inclusion = ? AND role_inclusion = ? AND
                update_epoch_inclusion < ?},
        $self->get_id, $role, $now
    );
}

[agouaux]

well, the business of getting the error popup and the error in the logs is definitely because of the cache. If I make this simple change:

sub _get_admins {
    my $self = shift;

    my $admin_user = $self->_cache_get('admin_user');
##AAG    return $admin_user
##AAG        if $admin_user and @{$admin_user || []};

    my $sdm = Sympa::DatabaseManager->instance;

The error popup no longer appears when adding an address as both owner and editor with one 'Update'. (Also no error in the logs.)

I see that $self->_cache_publish_expiry('admin_user'); is used. However, when adding an address to both editor and admin at once, I imagine the mtime of the resulting sync file is going to be too soon, so this call seems to have little impact. (Though, I haven't printed out this mtime value so this is only a guess.)

I'd hate to disable the cache altogether, though.

What would happen if this cache expiry file was missing altogether? Perhaps the WWW interface should pass an argument so that is done, so basically no caching when doing an edit via the WWW client?

[agouaux]

my-sympa-hacks.txt

Well, this patch seems to be working. So far all the above mentioned errors are not present.

It contains the code for _update_inclusion_table mentioned previously. It also does a force load into the admin cache when an owner or editor is added, removed, or updated.

[ikedas]

Does this feature affect?

[agouaux]

I don’t see how it would be at all related. I didn’t change any of the actual SQL.

…

On Dec 20, 2017, at 4:43 AM, IKEDA Soji ***@***.***> wrote: Does this feature affect? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[ikedas]

Please try with this patch:

diff --git a/src/lib/Sympa/DatabaseDriver/MySQL.pm b/src/lib/Sympa/DatabaseDriver/MySQL.pm
index 9afdfa1..14c8157 100644
--- a/src/lib/Sympa/DatabaseDriver/MySQL.pm
+++ b/src/lib/Sympa/DatabaseDriver/MySQL.pm
@@ -40,6 +40,7 @@ sub build_connect_string {
 
     my $connect_string =
         'DBI:mysql:' . $self->{'db_name'} . ':' . $self->{'db_host'};
+    $connect_string .= ';mysql_client_found_rows=1';
     $connect_string .= ';port=' . $self->{'db_port'}
         if defined $self->{'db_port'};
     $connect_string .= ';' . $self->{'db_options'}

[agouaux]

I will, but I don't think it'll make any difference to what I was seeing.

I put in a ton, and I mean a TON of syslog statements all throughout the code to get a better idea of what was going on. What I discovered is that when the same address was added as owner and editor at once, the loop that goes through the admins the second time around didn't know the admin had been added to the table. That's because the vehicle that determined when another SELECT was preformed to update the cache is based on the mtime of a file. This mtime, as I'm sure you know, is the number of seconds since EPOCH--a value that on a machine of any speed at all isn't granular enough. So, in that logic loop, mtime was checked here:

sub _cache_get {
    my $self   = shift;
    my $type   = shift;

    my $lasttime = $self->{_mtime}{$type};
    my $mtime;
    if ($type eq 'total' or $type eq 'is_list_member') {
        $mtime = $self->_cache_read_expiry('member');
    } else {
        $mtime = $self->_cache_read_expiry($type);
    }
    $self->{_mtime}{$type} = $mtime;

    return undef unless defined $lasttime and defined $mtime;
    return undef if $lasttime < $mtime;   ### <----<<<<<
    return $self->{_cached}{$type};
}

and since the milliseconds since the admin was already added to the table, the cache had become stale. This was quite reproducible.

So, what I did is add this to the end of add_list_admin, update_list_admin, delete_list_admin:

    $log->syslog('debug2', "force reload of cache with get_admins($role)");
    $self->get_admins($role, force => 1);  ### AAG

then I just added this to get_admins:

##AAG    my $admin_user = $self->_get_admins;
    my $admin_user = $self->_get_admins(force => $options{force});  ### AAG
    return unless $admin_user;    # Returns void.

and this to _get_admins:

sub _get_admins {
    my $self = shift;
    my %options = @_;

    my $admin_user = $self->_cache_get('admin_user');
    unless ($options{force}) {    ### AAG
        return $admin_user
            if $admin_user and @{$admin_user || []};
    };  ### AAG

Effectively, at least for updating admins, ignoring whatever the mtime on that file was. With that change, right after an admin is updated, a select is done for that $role in the user_admin table, thereby updating the cache. The next time sync_include_admin looped through to see if that admin needed to be added, they were now in the cache, and so no errors about adding a duplicate entry.

I don't know if it's the best way to go about rectifying the issue, but it seems to work predictably, the SQL server isn't doing SELECT on user_admin constantly (say if cache entirely disabled), and I'm not seeing any errors in the logs, nor error pop-ups in the web GUI.

[ikedas]

On my side it could applied to 6.2.24.

Anyway, please see the documentation to build with 6.2-branch (see descriptions about development version). Thanks.

[agouaux]

Well, I just seem to find ways to be contrary! ;-) It's truly not my intention.

# /deploy/src/sympa
: aisdsympa01$; tar zxf sympa-6.2.24.tar.gz

# /deploy/src/sympa/sympa-6.2.24
: aisdsympa01$; patch -p1 < ../ikedas-issue-11_try2.patch
patching file src/cgi/wwsympa.fcgi.in
Hunk #1 succeeded at 10780 (offset -5 lines).
patching file src/lib/Sympa/DatabaseDescription.pm
patching file src/lib/Sympa/List.pm

ok, so trying this..

# /deploy/src/sympa
: aisdsympa01$; git clone https://github.com/sympa-community/sympa.git sympa-6.2-head
Cloning into 'sympa-6.2-head'...
remote: Counting objects: 71343, done.
remote: Compressing objects: 100% (4/4), done.
remote: Total 71343 (delta 0), reused 2 (delta 0), pack-reused 71339
Receiving objects: 100% (71343/71343), 123.17 MiB | 7.26 MiB/s, done.
Resolving deltas: 100% (59642/59642), done.

# /deploy/src/sympa
: aisdsympa01$; cd sympa-6.2-head

# /deploy/src/sympa/sympa-6.2-head
: aisdsympa01$; git checkout -b sympa-6.2 origin/sympa-6.2
Branch sympa-6.2 set up to track remote branch sympa-6.2 from origin.
Switched to a new branch 'sympa-6.2'

# /deploy/src/sympa/sympa-6.2-head
: aisdsympa01$; autoreconf -i
configure.ac:31: warning: macro 'AM_PO_SUBDIRS' not found in library
configure.ac:6: installing './install-sh'
configure.ac:6: installing './missing'
Makefile.am: installing './depcomp'
configure.ac:31: error: possibly undefined macro: AM_PO_SUBDIRS
      If this token and others are legitimate, please use m4_pattern_allow.
      See the Autoconf documentation.
autoreconf: /usr/bin/autoconf failed with exit status: 1

# /deploy/src/sympa/sympa-6.2-head
: aisdsympa01$; autoreconf --version
autoreconf (GNU Autoconf) 2.69

[agouaux]

Well, looks like a configure script was created nonetheless, so I proceeded with the install. This is what I did:

# systemctl stop sympa
# systemctl stop httpd
# rm -rf  /deploy/sympa/bin
# ./configure --prefix=/deploy/sympa \
              --with-perl=/usr/local/bin/perl \
              --with-aliases_file=/deploy/sympa/etc/sympa_aliases \
              --with-postmap=/usr/sbin/postmap
# make
# make install
# /bin/cp -p /deploy/sympa/bin/wwsympa.fcgi /deploy/www/
# /bin/cp -p /deploy/sympa/bin/sympa_soap_server-wrapper.fcgi /deploy/www/
# /deploy/sympa/bin/sympa_wizard.pl --check
# systemctl start sympa
# systemctl start httpd

(/deploy/www is where Apache looks for the fcgi scripts.)

Sadly, when I try to add the same address for both owner and editor, then click Update, I still get the error pop-up in the screen, and this is logged.

Jan 29 17:52:28 aisdsympa01 wwsympa[26417]: err main::#1607 > main::do_edit_list#10593 > Sympa::List::sync_include_admin#7164 > Sympa::List::add_list_admin#397
8 > Sympa::Database::do_prepared_query#382 Unable to execute SQL statement "INSERT INTO admin_table (user_admin, comment_admin, list_admin, robot_admin, date_a
dmin, update_admin, reception_admin, visibility_admin, subscribed_admin, included_admin, include_sources_admin, role_admin, info_admin, profile_admin) VALUES (
?, ?, ?, ?, FROM_UNIXTIME(1517269948), FROM_UNIXTIME(1517269948), ?, ?, ?, ?, ?, ?, ?, ?)": (23000) Duplicate entry 'dlists.xxx.edu-stest1-editor-do-not-r
eply@tlists.xxx.e' for key 'PRIMARY'
Jan 29 17:52:28 aisdsympa01 wwsympa[26417]: err main::#1607 > main::do_edit_list#10593 > Sympa::List::sync_include_admin#7164 > Sympa::List::add_list_admin#400
9 Unable to add admin do-not-reply@tlists.xxx.edu to table admin_table for list Sympa::List <stest1@dlists.xxx.edu>:
Jan 29 17:52:28 aisdsympa01 wwsympa[26417]: err main::#1607 > main::do_edit_list#10593 > Sympa::List::sync_include_admin#7166 Failed to add new editor(s) to li
st Sympa::List <stest1@dlists.xxx.edu>

[ikedas]

@agouaux, can you show the content of admin_table before and after operation on web UI? Querying MySQL:

SELECT user_admin, role_admin, subscribed_admin, included_admin
FROM admin_table
WHERE list_admin = 'stest1' AND robot_admin = 'dlists.xxx.edu';

[agouaux]

mysql> SELECT user_admin, role_admin, subscribed_admin, included_admin
    -> FROM admin_table
    -> WHERE list_admin = 'stest1' AND robot_admin = 'dlists.xxx.edu';
+-------------------------+------------+------------------+----------------+
| user_admin              | role_admin | subscribed_admin | included_admin |
+-------------------------+------------+------------------+----------------+
| postmaster@xxx.edu      | owner      |                1 |              0 |
+-------------------------+------------+------------------+----------------+
1 row in set (0.00 sec)



Jan 31 17:29:51 aisdsympa01 wwsympa[32737]: info main::do_edit_list() [robot dlists.xxx.edu] [session 53129586679657] [client 10.182.70.130] [user u1@xxx.edu] [list stest1]
Jan 31 17:29:51 aisdsympa01 wwsympa[32737]: notice Sympa::Spindle::ProcessTemplate::_twist() Processing Sympa::Message::Template <stest1@dlists.xxx.edu.1517441391.32737,4207>; envelope_sender=stest1-owner@dlists.xxx.edu; message_id=sympa.1517441391.32737.744@dlists.xxx.edu; recipients=do-not-reply@lists.xxx.edu; sender=sympa@dlists.xxx.edu; template=user_notification; type=added_as_listadmin
Jan 31 17:29:51 aisdsympa01 wwsympa[32737]: notice Sympa::Bulk::store() Message Sympa::Message::Template <stest1@dlists.xxx.edu.1517441391.32737,4207> is stored into bulk spool as <5.5.1517441391.1517441391.967475.stest1@dlists.xxx.edu_s,32737,6271>
Jan 31 17:29:51 aisdsympa01 wwsympa[32737]: notice Sympa::Spindle::ProcessTemplate::_twist() Processing Sympa::Message::Template <stest1@dlists.xxx.edu.1517441391.32737,400>; envelope_sender=stest1-owner@dlists.xxx.edu; message_id=sympa.1517441391.32737.113@dlists.xxx.edu; recipients=do-not-reply@lists.xxx.edu; sender=sympa@dlists.xxx.edu; template=user_notification; type=added_as_listadmin
Jan 31 17:29:51 aisdsympa01 wwsympa[32737]: notice Sympa::Bulk::store() Message Sympa::Message::Template <stest1@dlists.xxx.edu.1517441391.32737,400> is stored into bulk spool as <5.5.1517441391.1517441391.983231.stest1@dlists.xxx.edu_s,32737,9732>
Jan 31 17:29:52 aisdsympa01 wwsympa[32737]: err main::#1607 > main::do_edit_list#10593 > Sympa::List::sync_include_admin#7164 > Sympa::List::add_list_admin#3978 > Sympa::Database::do_prepared_query#382 Unable to execute SQL statement "INSERT INTO admin_table (user_admin, comment_admin, list_admin, robot_admin, date_admin, update_admin, reception_admin, visibility_admin, subscribed_admin, included_admin, include_sources_admin, role_admin, info_admin, profile_admin) VALUES (?, ?, ?, ?, FROM_UNIXTIME(1517441392), FROM_UNIXTIME(1517441392), ?, ?, ?, ?, ?, ?, ?, ?)": (23000) Duplicate entry 'dlists.xxx.edu-stest1-editor-do-not-reply@lists.xxx.ed' for key 'PRIMARY'
Jan 31 17:29:52 aisdsympa01 wwsympa[32737]: err main::#1607 > main::do_edit_list#10593 > Sympa::List::sync_include_admin#7164 > Sympa::List::add_list_admin#4009 Unable to add admin do-not-reply@lists.xxx.edu to table admin_table for list Sympa::List <stest1@dlists.xxx.edu>:
Jan 31 17:29:52 aisdsympa01 wwsympa[32737]: err main::#1607 > main::do_edit_list#10593 > Sympa::List::sync_include_admin#7166 Failed to add new editor(s) to list Sympa::List <stest1@dlists.xxx.edu>
Jan 31 17:29:52 aisdsympa01 wwsympa[32737]: notice Sympa::Spindle::ProcessTemplate::_twist() Processing Sympa::Message::Template <stest1@dlists.xxx.edu.1517441392.32737,9013>; envelope_sender=stest1-owner@dlists.xxx.edu; message_id=sympa.1517441392.32737.184@dlists.xxx.edu; recipients=ARRAY; sender=sympa@dlists.xxx.edu; template=listmaster_notification; type=web_intern_error; action=Command process
Jan 31 17:29:52 aisdsympa01 wwsympa[32737]: notice Sympa::Bulk::store() Message Sympa::Message::Template <stest1@dlists.xxx.edu.1517441392.32737,9013> is stored into bulk spool as <1.5.1517441392.1517441392.166090.stest1@dlists.xxx.edu_s,32737,2574>
Jan 31 17:29:52 aisdsympa01 wwsympa[32737]: info main::do_edit_list() [robot dlists.xxx.edu] [session 53129586679657] [client 10.182.70.130] [user u1@xxx.edu] [list stest1] Failed
Jan 31 17:29:52 aisdsympa01 wwsympa[32737]: info Sympa::Session::renew() [robot dlists.xxx.edu] [session 53129586679657] [client 10.182.70.130] [user u1@xxx.edu] new session 04956685558825
Jan 31 17:29:52 aisdsympa01 bulk[31888]: notice Sympa::Spindle::ProcessOutgoing::_twist() Start sending message Sympa::Message <1.5.1517441392.1517441392.166090.stest1@dlists.xxx.edu_s,32737,2574/s> to Sympa::List <stest1@dlists.xxx.edu> (priority 1) (starting 0 seconds after scheduled expedition date)
Jan 31 17:29:52 aisdsympa01 bulk[31888]: notice Sympa::Mailer::store() Forked process 41860: /usr/sbin/sendmail -oi -odi -oem -f 'sympa-request@dlists.xxx.edu' -- u1@xxx.edu a.goo0h@gmail.com
Jan 31 17:29:52 aisdsympa01 bulk[31888]: notice Sympa::Mailer::store() Done sending message Sympa::Message <1.5.1517441392.1517441392.166090.stest1@dlists.xxx.edu_s,32737,2574/s> for Sympa::List <stest1@dlists.xxx.edu> (priority 1) in 0 seconds since scheduled expedition date
Jan 31 17:29:52 aisdsympa01 bulk[31888]: notice Sympa::Spindle::ProcessOutgoing::_twist() Start sending message Sympa::Message <5.5.1517441391.1517441391.967475.stest1@dlists.xxx.edu_s,32737,6271/s> to Sympa::List <stest1@dlists.xxx.edu> (priority 5) (starting 1 seconds after scheduled expedition date)
Jan 31 17:29:52 aisdsympa01 bulk[31888]: notice Sympa::Mailer::store() Forked process 41863: /usr/sbin/sendmail -oi -odi -oem -f 'stest1-owner@dlists.xxx.edu' -- do-not-reply@lists.xxx.edu
Jan 31 17:29:53 aisdsympa01 bulk[31888]: notice Sympa::Mailer::store() Done sending message Sympa::Message <5.5.1517441391.1517441391.967475.stest1@dlists.xxx.edu_s,32737,6271/s> for Sympa::List <stest1@dlists.xxx.edu> (priority 5) in 2 seconds since scheduled expedition date
Jan 31 17:29:53 aisdsympa01 bulk[31888]: notice Sympa::Spindle::ProcessOutgoing::_twist() Start sending message Sympa::Message <5.5.1517441391.1517441391.983231.stest1@dlists.xxx.edu_s,32737,9732/s> to Sympa::List <stest1@dlists.xxx.edu> (priority 5) (starting 2 seconds after scheduled expedition date)
Jan 31 17:29:53 aisdsympa01 bulk[31888]: notice Sympa::Mailer::store() Forked process 41874: /usr/sbin/sendmail -oi -odi -oem -f 'stest1-owner@dlists.xxx.edu' -- do-not-reply@lists.xxx.edu
Jan 31 17:29:53 aisdsympa01 bulk[31888]: notice Sympa::Mailer::store() Done sending message Sympa::Message <5.5.1517441391.1517441391.983231.stest1@dlists.xxx.edu_s,32737,9732/s> for Sympa::List <stest1@dlists.xxx.edu> (priority 5) in 2 seconds since scheduled expedition date



mysql> SELECT user_admin, role_admin, subscribed_admin, included_admin FROM admin_table WHERE list_admin = 'stest1' AND robot_admin = 'dlists.xxx.edu';
+---------------------------------+------------+------------------+----------------+
| user_admin                      | role_admin | subscribed_admin | included_admin |
+---------------------------------+------------+------------------+----------------+
| do-not-reply@lists.xxx.edu      | owner      |                1 |              0 |
| postmaster@xxx.edu              | owner      |                1 |              0 |
| do-not-reply@lists.xxx.edu      | editor     |                1 |              0 |
+---------------------------------+------------+------------------+----------------+
3 rows in set (0.00 sec)

[ikedas]

I missed a change. @agouaux, can you please apply this additional patch (keeping previous patch applied), and try again?

[agouaux]

OK, I blew away my git pull and did a fresh, new git pull of everything. I built/deployed sympa, and it now looks as if this particular error is now gone! :-)

[ikedas]

Really? @agouaux, thanks for testing! If you don't find problem, please use these patches for the time being.

However, I think these would not be better to be included into Sympa.

Because, what I know by trials so far is that, owner and editor parameters in list config file are useless. Their values often drop behind information in database, and cause spurious errors during updating information. My patches essentially throw parameter values in config file away and use only database. I guess this may be done in simpler way.

I'll submit another PR in some other day (by the time of 6.2.26b.2?).

---

Then, I'll investigate another problem (key errors on inclusion_table).

[agouaux]

Well, I think I finally figured out the DUPLICATE errors I was getting during attempts to update admin_table.

These errors were occurring for lists that included other lists for either the owner and editor. On these other lists, in the example below, "etech", there were some members with addresses in mixed case:

Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug2 Sympa::List::sync_include_admin() Adding owner Dung.Dinh@xxx.org to list ecs.mse.fac Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug2 Sympa::List::sync_include_admin() Adding owner Eric.Laws@xxx.org to list ecs.mse.fac Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug2 Sympa::List::sync_include_admin() Adding owner James.Cheatham@xxx.org to list ecs.mse.fac Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug2 Sympa::List::sync_include_admin() Adding owner Steve.Martindell@xxx.org to list ecs.mse.fac

However, somewhere along the process of adding addresses into the DB, they are converted to all lower-case, as they should. Yet, the logic that goes through and compares the old addresses and those that need to be added, it wasn't first lower-casing the new addresses. So, it tried to add the newer (mixed-case) addresses. When it did so, however, that's when it lower-cased the address, which meant it was adding an address already there. This resulted in the DUPLICATE errors.

Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#3997 > Sympa ::Database::do_prepared_query#382 Unable to execute SQL statement "INSERT INTO admin_table (user_admin, comment_admin, list_admin, robot_admin, date_admin, update_admin, reception_admin, visibility_admin, subscribed_admi n, included_admin, include_sources_admin, role_admin, info_admin, profile_admin) VALUES (?, ?, ?, ?, FROM_UNIXTIME(1518373351), FROM_UNIXTIME(1518373351), ?, ?, ?, ?, ?, ?, ?, ?)": (23000) Duplicate entry 'lists.xxx .org-ecs.mse.fac-owner-dung.dinh@xxx.org' for key 'PRIMARY' Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#4028 Unable to add admin dung.dinh@xxx.org to table admin_table for list Sympa::List <ecs.mse.fac@lists.xxx.org>: Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#3997 > Sympa ::Database::do_prepared_query#382 Unable to execute SQL statement "INSERT INTO admin_table (user_admin, comment_admin, list_admin, robot_admin, date_admin, update_admin, reception_admin, visibility_admin, subscribed_admi n, included_admin, include_sources_admin, role_admin, info_admin, profile_admin) VALUES (?, ?, ?, ?, FROM_UNIXTIME(1518373351), FROM_UNIXTIME(1518373351), ?, ?, ?, ?, ?, ?, ?, ?)": (23000) Duplicate entry 'lists.xxx .org-ecs.mse.fac-owner-eric.laws@xxx.org' for key 'PRIMARY' Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#4028 Unable to add admin eric.laws@xxx.org to table admin_table for list Sympa::List <ecs.mse.fac@lists.xxx.org>: Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#3997 > Sympa ::Database::do_prepared_query#382 Unable to execute SQL statement "INSERT INTO admin_table (user_admin, comment_admin, list_admin, robot_admin, date_admin, update_admin, reception_admin, visibility_admin, subscribed_admi n, included_admin, include_sources_admin, role_admin, info_admin, profile_admin) VALUES (?, ?, ?, ?, FROM_UNIXTIME(1518373351), FROM_UNIXTIME(1518373351), ?, ?, ?, ?, ?, ?, ?, ?)": (23000) Duplicate entry 'lists.xxx .org-ecs.mse.fac-owner-james.cheatham@xxx.org' for key 'PRIMARY' Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#4028 Unable to add admin james.cheatham@xxx.org to table admin_table for list Sympa::List <ecs.mse.fac@lists.xxx.org>: Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting Feb 11 12:22:31 aispsympa01 task_manager[58589]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#3997 > Sympa ::Database::do_prepared_query#382 Unable to execute SQL statement "INSERT INTO admin_table (user_admin, comment_admin, list_admin, robot_admin, date_admin, update_admin, reception_admin, visibility_admin, subscribed_admi n, included_admin, include_sources_admin, role_admin, info_admin, profile_admin) VALUES (?, ?, ?, ?, FROM_UNIXTIME(1518373351), FROM_UNIXTIME(1518373351), ?, ?, ?, ?, ?, ?, ?, ?)": (23000) Duplicate entry 'lists.xxx .org-ecs.mse.fac-owner-steve.martindell@xxx.e' for key 'PRIMARY' Feb 11 12:22:31 aispsympa01 task_manager[58589]: err main::#260 > Sympa::Task::list_tasks#117 > Sympa::Task::new#66 > Sympa::List::new#399 > Sympa::List::sync_include_admin#7183 > Sympa::List::add_list_admin#4028 Unable to add admin steve.martindell@xxx.org to table admin_table for list Sympa::List <ecs.mse.fac@lists.xxx.org>

When I converted all the members on the "etech" list (removed them, then added them back in lower-case), the errors and problems disappeared.

For now I've instructed the admin of the "etech" list to please be sure to only add the addresses in lower-case.

[agouaux]

Actually, the case thing also appears to be an issue when you include the members of one list (a) to the members of another list (b). So, if First.Last@xxx.org is a member of (a), and list (b) includes the members of list (a), then there will be errors like so:

main::execute#808 > main::cmd_process#878 > main::sync_include#2063 > Sympa::List::sync_include#6844 > Sympa::List::add_list_member#3899 Unable to add subscriber first.last@xxx.org to table subscriber_table for list (b)

Notice the error message as "first.last", and not "First.Last".

[ikedas]

Modification to fix the bug fundamentally needs some time, and I will apply tentative patch above. Milestone is postponed to 6.2.28.

[ikedas]

Fix was merged and will be released as a part of next beta, 6.2.33b.1. This issue is closed. Thanks!