View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000450SOGoWeb Preferencespublic2010-02-22 16:252010-03-12 21:40
Reporterkoen Assigned Towsourdeau 
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionfixed 
Product Version1.2.1 
Target Version1.2.2Fixed in Version1.2.2 
Summary0000450: Sieve script not activated
Description

Hi,

We are testing the Vacation module included in SOGo.
So far, SOGo creates the sieve script and puts it on the server using Managesieve.
However, the script is not activated.
The script is saved as ~/sieve/sogo.sieve .
When we manually connect to the managesieve service using telnet and activate the script, managesieve creates a symlink called .dovecot.sieve to the script. After which the vacation notice works.

The SOGo log contains these entries:
Feb 22 16:34:47 sogod: SOGo watchdog [9158]: <0x109D1F60[SOGoMailAccount]:USER_A_DOMAIN_D_TLD_A_mail_D_SERVER_D_net> WARNING: Could not delete Sieve script - continuing...: {RawResponse = "{ok = NO; }"; result = NO; }
Feb 22 16:34:47 sogod: SOGo watchdog [9158]: [ERROR] <0x109D1F60[SOGoMailAccount]:USER_A_DOMAIN_D_TLD_A_mail_D_SERVER_D_net> Could not upload Sieve script: {RawResponse = "{}"; result = NO; }

We've tried to debug this by setting up a packet sniffer between the managesieve server and SOGo, relevant results will be added as additional information (the packet list is continuous, no packets were left out).
From these packets we could see that SOGo actually logs in (packet 01 -> 07 & 15->23), performs his first command (packet 8 -> 9 & 24 -> 25) and then generates an error on the server (packet 10 -> 11 & 26 -> 27). After this it seems the process can continue without errors (packet 12 -> 14).
Could this be the cause of the error?

We are using SOGo 1.2.1-1.el5 from the yum repository.
Our operating system is: CentOS release 5.4 (Final)
The sieve server runs these versions:
dovecot-1.2.10-2_107.el5
dovecot-sieve-0.1.15-4.el5
dovecot-managesieve-0.11.11-2

The problem can easily be reproduced by simply logging on, going to the preferences in your account, active the vacation auto-reply, save and close.
(In this test & packet listing we've also deactivated the vacation auto-reply.)

I hope I've provided you with enough information about this problem.

Kind regards,

Koen

Additional Information

Packet 01: mailserver -> SOGo

jMm>'DE!@@

N.>8.
3B-"IMPLEMENTATION" "dovecot"
"SIEVE" "comparator-i;octet comparator-i;ascii-casemap fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date"
"SASL" "PLAIN"
"STARTTLS"
"NOTIFY" "mailto"
"VERSION" "1.0"
OK "Dovecot ready."

Packet 02: SOGo -> mailserver

'DjMmE4@@/

8N/o6W
B-3

Packet 03: SOGo -> mailserver

'DjMmE@@

8N/o6
B-3AUTHENTICATE "PLAIN" {72+}
DELETEDHASH

Packet 04: mailserver -> SOGo

jMm>'DE4"@@

N/o>.
4B-

Packet 05: SOGo -> mailserver

'DjMmE6@@+

N/o6
B-4

Packet 06: mailserver -> SOGo

jMm>'DE4#@@

N/o>.
4B-

Packet 07: mailserver -> SOGo

jMm>'DEE$@@

N/o>.j
:B-OK "Logged in."

Packet 08: SOGo -> mailserver

'DjMmEI@@

N/6
B-:DELETESCRIPT "sogo"

Packet 09: mailserver -> SOGo

jMm>'DE_%@@

N/>.j
;B-NO (NONEXISTENT) "Script does not exist."

Packet 10: SOGo -> mailserver

'DjMmE6@@)

N/6
B-;

Packet 11: mailserver -> SOGo

jMm>'DEj&@@

N/>.|
;B-NO "Error in MANAGESIEVE command : Unknown command."

Packet 12: SOGo -> mailserver

'DjMmE@@Y

N/6
B-;PUTSCRIPT "sogo" {182+}
require ["vacation"];
vacation :days 1 :addresses ["MASKEDMAIL"] text:
Hi,

This is an automated test message, please discard.

Kind regards,

.
;

Packet 13: SOGo -> mailserver

'DjMmE4@@)

N/6
B-;

Packet 14: SOGo -> mailserver

'DjMmE</5@@k

l
B4

Packet 15: mailserver -> SOGo

jMm>'DE<@@&

RB4

Packet 16: SOGo -> mailserver

'DjMmE4/6@@k

.
B4R

Packet 17: mailserver -> SOGo

jMm>'DE@@L

.*
RB4"IMPLEMENTATION" "dovecot"
"SIEVE" "comparator-i;octet comparator-i;ascii-casemap fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date"
"SASL" "PLAIN"
"STARTTLS"
"NOTIFY" "mailto"
"VERSION" "1.0"
OK "Dovecot ready."

Packet 18: SOGo -> mailserver

'DjMmE4/7@@k

46
B4R

Packet 19: SOGo -> mailserver

'DjMmE/8@@k

46
B4RAUTHENTICATE "PLAIN" {72+}
DELETEDHASH

Packet 20: mailserver -> SOGo

jMm>'DE4@@

44.2
RB4

Packet 21: SOGo -> mailserver

'DjMmE6/9@@k

446
B4R

Packet 22: mailserver -> SOGo

jMm>'DE4@@

46.0
RB4

Packet 23: mailserver -> SOGo

jMm>'DEE@@

46.
TB4OK "Logged in."

Packet 24: SOGo -> mailserver

'DjMmEI/:@@k

6E6
B4TDELETESCRIPT "sogo"

Packet 25: mailserver -> SOGo

jMm>'DER@@

EK.
TB4OK "Deletescript completed."

Packet 26: SOGo -> mailserver

'DjMmE6/;@@k

Kc6
B4T

Packet 27: mailserver -> SOGo

jMm>'DEj@@n

cM.
VB4NO "Error in MANAGESIEVE command : Unknown command."

TagsNo tags attached.

Relationships

Relationship GraphDependency Graph
duplicate of 0000398 resolvedludovic defaultbc link not created in sieve directory when activating Vacation or Forward scripts 

Activities

ludovic

ludovic

2010-03-08 16:45

administrator   ~0000675

Can you retry with the latest nightly build?
aschild

aschild

2010-03-08 17:40

reporter   ~0000679

Nope, still problems with 1.2.2.20100308

When no sogo script exists, then the sogo.bc and sogo.script are created on the server, but the symlink is not created.
When we then resave the filter, the @defaultbc is correctly created/linked to the sogo.bc.

When we then remove/deactive all entries, the @defaultbc is removed, but on activation it is only created on the second save.

André
wsourdeau

wsourdeau

2010-03-11 21:58

viewer   ~0000714

Hi Guido,

Can you try again with the next nigthlies?
aschild

aschild

2010-03-12 06:37

reporter   ~0000715

No,

it does still not work.
The script is uploaded, but no symlink is made on the first save.
On the second save the symlink is then made.

Here the traffic of the first save as seen by tcpdump:

"IMPLEMENTATION" "Cyrus timsieved v2.2.12-Debian-2.2.12-4ubuntu1"
"SASL" "PLAIN"
"SIEVE" "fileinto reject envelope vacation imapflags notify subaddress relational comparator-i;ascii-numeric regex"
"STARTTLS"
OK
AUTHENTICATE "PLAIN" {52+}
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
OK
DELETESCRIPT "sogo"
NO "Error deleting script"
PUTSCRIPT "sogo" {451+}
require ["vacation"];
if allof ( not exists ["list-help", "list-unsubscribe", "list-subscribe", "list-owner", "list-post", "list-archive", "list-id", "Mailing-List"], not header :comparator "i;ascii-casemap" :is "Precedence" ["list", "bulk", "junk"], not header :comparator "i;ascii-casemap" :matches "To" "Multiple recipients of*" ) {vacation :days 1 :addresses ["andre@schild.ws"] text:
Ferien von wann bis wann ?
............
Zeile 3
.
;
}
OK
OK "Logout Complete"

So the script is saved on the server, but not yet activated.
Here then the traffic of the second save:

"IMPLEMENTATION" "Cyrus timsieved v2.2.12-Debian-2.2.12-4ubuntu1"
"SASL" "PLAIN"
"SIEVE" "fileinto reject envelope vacation imapflags notify subaddress relational comparator-i;ascii-numeric regex"
"STARTTLS"
OK
AUTHENTICATE "PLAIN" {52+}
yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy
OK
DELETESCRIPT "sogo"
OK
PUTSCRIPT "sogo" {451+}
require ["vacation"];
if allof ( not exists ["list-help", "list-unsubscribe", "list-subscribe", "list-owner", "list-post", "list-archive", "list-id", "Mailing-List"], not header :comparator "i;ascii-casemap" :is "Precedence" ["list", "bulk", "junk"], not header :comparator "i;ascii-casemap" :matches "To" "Multiple recipients of*" ) {vacation :days 1 :addresses ["andre@schild.ws"] text:
Ferien von wann bis wann ?
............
Zeile 3
.
;
}
OK
SETACTIVE "sogo"
OK
OK "Logout Complete"

I see two differences:

In the first activation, there is no existing sogo script, so the deletion fails.
The new script is then uploaded, but the SETACTIVE is missing.
In the second activation, the deletion of the sogo script works ok, then it's uploaded and finaly the SETACTIVE is executed.

André
aschild

aschild

2010-03-12 07:23

reporter   ~0000716

Here what I see in the sogo.log on the first upload:

Mar 12 08:06:59 sogod: SOGo watchdog [23900]: <0x01E4F1F0[SOGoMailAccount]:andre_A_schild_D_ws_A_mail1_D_aarboard_D_ch> WARNING: Could not d
elete Sieve script - continuing...: {RawResponse = "{ok = NO; reason = \"Error deleting script\"; }"; result = NO; }
Mar 12 08:06:59 sogod: SOGo watchdog [23900]: [ERROR] <0x01E4F1F0[SOGoMailAccount]:andre_A_schild_D_ws_A_mail1_D_aarboard_D_ch> Could not up
load Sieve script: {RawResponse = "{}"; result = NO; }
127.0.0.1 - - [12/Mar/2010:08:06:59 GMT] "POST /SOGo/so/andre@schild.ws/preferences HTTP/1.1" 200 256/1959 0.060 - - 0

Here the tcp dump of the conversion:
"IMPLEMENTATION" "Cyrus timsieved v2.2.12-Debian-2.2.12-4ubuntu1"
"SASL" "PLAIN"
"SIEVE" "fileinto reject envelope vacation imapflags notify subaddress relational comparator-i;ascii-numeric regex"
"STARTTLS"
OK
AUTHENTICATE "PLAIN" {52+}
zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz
OK
DELETESCRIPT "sogo"
NO "Error deleting script"
PUTSCRIPT "sogo" {212+}
require ["fileinto"];
if anyof (header :contains "subject" "[sogo]") {
fileinto "Listserver/Sogo";
}
elsif anyof (header :contains "subject" "[OSM-newbies]") {
fileinto "Listserver/OSM-newbies";
}
OK
OK "Logout Complete"

Looking at the SOGoMailAccount.m everything looks fine, so I assume that probably in the sope-mime/NGImap4/NGSieveClient.m file, the status of the failed DELETESCRIPT is somehow retained and then also returned for the following upload script command...

André
wsourdeau

wsourdeau

2010-03-12 20:31

viewer   ~0000719

Hi André,

Are you sure you restarted SOGo properly after the update?
This is exactly the issue that I fixed yesterday so I would be a bit puzzled otherwise...
aschild

aschild

2010-03-12 21:05

reporter   ~0000720

Strange...

here the update log of this morning:

Processing triggers for man-db ...
Setting up dpkg-dev (1.14.29) ...
Setting up linux-libc-dev (2.6.26-21lenny4) ...
Setting up libsope-xml4.9 (4.9.r1664.20100311) ...
Setting up libsope-core4.9 (4.9.r1664.20100311) ...
Setting up libsope-mime4.9 (4.9.r1664.20100311) ...
Setting up libsope-appserver4.9 (4.9.r1664.20100311) ...
Setting up libsope-gdl1-4.9 (4.9.r1664.20100311) ...
Setting up libsope-ldap4.9 (4.9.r1664.20100311) ...
Setting up sope4.9-libxmlsaxdriver (4.9.r1664.20100311) ...
Setting up sope4.9-gdl1-postgresql (4.9.r1664.20100311) ...
Setting up sope4.9-gdl1-mysql (4.9.r1664.20100311) ...
Setting up sogo (1.2.2.20100311) ...
Starting Scalable OpenGroupware.Org: sogo.
Setting up sope-tools (4.9.r1664.20100311) ...
Setting up sope4.9-appserver (4.9.r1664.20100311) ...
Log ended: 2010-03-12 06:21:50 (UTC)

Then the restart of sogo:

Times UTC+1
Mar 12 07:23:37 sogod: SOGo watchdog [8803]: <0x0x17b4700[WOWatchDogChild]> child 8804 exited
Mar 12 07:23:37 sogod: SOGo watchdog [8803]: <0x0x177d1b0[WOWatchDog]> all children exited. We now ter
minate.
Mar 12 07:23:38 sogod: SOGo watchdog [23804]: [WARN] <0x0x1710fe0[WOWatchDog]> 'WOHttpAllowHost' is ig
nored in watchdog mode, use a real firewall instead
Mar 12 07:23:38 sogod: SOGo watchdog [23804]: <0x0x1710fe0[WOWatchDog]> listening on *:20000

Now this evening:

etting up libsope-xml4.9 (4.9.r1664.20100312) ...
Setting up libsope-core4.9 (4.9.r1664.20100312) ...
Setting up libsope-mime4.9 (4.9.r1664.20100312) ...
Setting up libsope-appserver4.9 (4.9.r1664.20100312) ...
Setting up libsope-gdl1-4.9 (4.9.r1664.20100312) ...
Setting up libsope-ldap4.9 (4.9.r1664.20100312) ...
Setting up sope4.9-libxmlsaxdriver (4.9.r1664.20100312) ...
Setting up sope4.9-gdl1-postgresql (4.9.r1664.20100312) ...
Setting up sope4.9-gdl1-mysql (4.9.r1664.20100312) ...
Setting up sogo (1.2.2.20100312) ...
Starting Scalable OpenGroupware.Org: sogo.
Setting up sope-tools (4.9.r1664.20100312) ...
Setting up sope4.9-appserver (4.9.r1664.20100312) ...
Log ended: 2010-03-12 20:53:30

And the sogo restart: (UTC+1)

Mar 12 21:53:38 sogod: SOGo watchdog [23899]: <0x0xdca300[WOWatchDog]> Terminating with signal 15
Mar 12 21:53:38 sogod: SOGo watchdog [23899]: <0x0xe01850[WOWatchDogChild]> sending terminate signal t
o pid 23900
Mar 12 21:53:38 sogod: SOGo watchdog [23899]: <0x0xe01850[WOWatchDogChild]> child 23900 exited
Mar 12 21:53:38 sogod: SOGo watchdog [23899]: <0x0xdca300[WOWatchDog]> all children exited. We now ter
minate.
Mar 12 21:53:39 sogod: SOGo watchdog [32682]: [WARN] <0x0x2604fe0[WOWatchDog]> 'WOHttpAllowHost' is ig
nored in watchdog mode, use a real firewall instead
Mar 12 21:53:39 sogod: SOGo watchdog [32682]: <0x0x2604fe0[WOWatchDog]> listening on *:20000

And now it works, thanks.

Looks like the debian builds this morning where still at 2010-03-11 level, instead of 2010-03-12.

Perhaps it would help, when you mention in which release the problem was fixed, so we don't hunt ghosts when some build/deployment fails.

Anyway, thanks a lot.

André
wsourdeau

wsourdeau

2010-03-12 21:38

viewer   ~0000721

Fixed in ae2731aedf2ba81e571b426efe36751b90702b6b.
wsourdeau

wsourdeau

2010-03-12 21:40

viewer   ~0000722

Hi André,

Yes and no... The 11th was clearly yesterday at the time, even for your timezone so I assumed that you would understand what "next nightlies" meant based at least on the date my message was written. What is useful to know is that we have a 6 hour offset with Western Europe, and the packages are built between 6 and 7 in the morning, which means 11 or 12 for you...

Issue History

Date Modified Username Field Change
2010-02-22 16:25 koen New Issue
2010-02-23 14:07 ludovic Target Version => 1.2.2
2010-03-08 16:45 ludovic Note Added: 0000675
2010-03-08 17:40 aschild Note Added: 0000679
2010-03-11 21:56 wsourdeau Fixed in Version => 1.2.2
2010-03-11 21:58 wsourdeau Note Added: 0000714
2010-03-12 06:37 aschild Note Added: 0000715
2010-03-12 07:23 aschild Note Added: 0000716
2010-03-12 20:31 wsourdeau Note Added: 0000719
2010-03-12 21:05 aschild Note Added: 0000720
2010-03-12 21:38 wsourdeau Note Added: 0000721
2010-03-12 21:38 wsourdeau Relationship added duplicate of 0000398
2010-03-12 21:38 wsourdeau Duplicate ID 0 => 398
2010-03-12 21:38 wsourdeau Status new => resolved
2010-03-12 21:38 wsourdeau Resolution open => fixed
2010-03-12 21:38 wsourdeau Assigned To => wsourdeau
2010-03-12 21:40 wsourdeau Note Added: 0000722