0000450: Sieve script not activated - SOGo | BTS

ID	Project	Category	View Status	Date Submitted	Last Update
0000450	SOGo	Web Preferences	public	2010-02-22 16:25	2010-03-12 21:40

Reporter	koen	Assigned To	~~wsourdeau~~
Priority	normal	Severity	minor	Reproducibility	always
Status	resolved	Resolution	fixed
Product Version	1.2.1
Target Version	1.2.2	Fixed in Version	1.2.2

Summary	0000450: 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."
Tags	No tags attached.

ludovic 2010-03-08 16:45 administrator ~0000675	Can you retry with the latest nightly build?

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~~ 2010-03-11 21:58 viewer ~0000714	Hi Guido, Can you try again with the next nigthlies?

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 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~~ 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 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~~ 2010-03-12 21:38 viewer ~0000721	Fixed in ae2731aedf2ba81e571b426efe36751b90702b6b.

~~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...

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