0000922: email-based alarms - SOGo

ID	Project	Category	View Status	Date Submitted	Last Update

0000922	SOGo	Backend Calendar	public	2010-10-24 15:47	2010-11-08 18:32

Reporter	wimmer	Assigned To	ludovic
Priority	normal	Severity	minor	Reproducibility	always
Status	resolved	Resolution	fixed
Product Version	nightly v2
Target Version	1.3.4	Fixed in Version	1.3.4

Summary	0000922: email-based alarms
Description	sogo-ealarms-notify doesn't send email-based alarms, it products error messages like: Oct 24 12:20:01 sogo-ealarms-notify [27953]: [ERROR] <0x0xf10a50[SOGoEMailAlarms Manager]> alarm number mismatch for record: {c_alarm_number = 0; c_name = "6CEC- 4CC40780-1-59E75680.ics"; c_path = "/Users/harryp/Calendar/personal"; c_recurren ce_id = "-2147483648"; c_uid = "6CEC-4CC40780-1-59E75680"; } I can set "Send an E-mail" Reminder Action in WebGUI and I see accordant record in the "sogo_alarms_folder" postgresql table. "c_alarm_number" column is set to 0 in all cases. I think I'm using correct sogod setting: sogod OCSEMailAlarmsFolderURL postgresql://sogo:xxx@localhost:5432/sogo/sogo_alarms_folder sogod SOGoEnableEMailAlarms YES
Tags	No tags attached.

wcronen 2010-10-24 17:58 reporter ~0001644	I'm having the same problem and I'm also getting a simular error message in the sogo.log

wbrune 2010-10-26 09:12 reporter ~0001656 Last edited: 2010-10-26 10:15	i had the same error message. i deleted the table and restartet sogo. the table was recreated. i think the table structure has changed, but did not verify that. the error message has gone, but i also do not get the email notification. update: the error message is there. i found the cron mail in the wrong email-folder.

~~wsourdeau~~ 2010-10-29 19:59 viewer ~0001666	Can you attach the event "6CEC-4CC40780-1-59E75680.ics" to help us ? Thanks

2010-10-29 20:12	event.txt (1,109 bytes) { c_content = "BEGIN:VCALENDAR^M VERSION:2.0^M PRODID:-//Inverse inc./SOGo 1.0//EN^M BEGIN:VEVENT^M UID:6CEC-4CC40780-1-59E75680^M SUMMARY:13^M CREATED:20101024T101819Z^M DTSTAMP:20101024T101819Z^M LAST-MODIFIED:20101024T153332Z^M DTSTART;TZID=/inverse.ca/20101018_1/Europe/Prague:20101024T190000^M DTEND;TZID=/inverse.ca/20101018_1/Europe/Prague:20101024T200000^M TRANSP:OPAQUE^M BEGIN:VALARM^M TRIGGER;RELATED=START;VALUE=DURATION:-PT40M^M ACTION:EMAIL^M ATTENDEE;CN=Harry Potter:mailto:harryp@civ.zcu.cz^M SUMMARY:13^M END:VALARM^M SEQUENCE:1^M END:VEVENT^M BEGIN:VTIMEZONE^M TZID:/inverse.ca/20101018_1/Europe/Prague^M X-LIC-LOCATION:Europe/Prague^M BEGIN:DAYLIGHT^M TZOFFSETFROM:+0100^M TZOFFSETTO:+0200^M TZNAME:CEST^M DTSTART:19700329T020000^M RRULE:FREQ=YEARLY;BYMONTH=3;BYDAY=-1SU^M END:DAYLIGHT^M BEGIN:STANDARD^M TZOFFSETFROM:+0200^M TZOFFSETTO:+0100^M TZNAME:CET^M DTSTART:19701025T030000^M RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=-1SU^M END:STANDARD^M END:VTIMEZONE^M END:VCALENDAR"; c_name = "6CEC-4CC40780-1-59E75680.ics"; }, event.txt (1,109 bytes)

2010-10-29 20:12	reminder.jpg (18,078 bytes) reminder.jpg (18,078 bytes)

wimmer 2010-10-29 20:13 reporter ~0001667	I used part of the "sogo-tool backup" for all cases...

wimmer 2010-10-29 20:30 reporter ~0001668	For clarification - that event had start time 13:00 when I created. So error log (Oct 24 12:20:01) is related to that time (minus 40 minutes before). After unsuccessful reminder attempt I changed its start time to 19:00. I tried to create new event just now and it has same problem - so when you will need some 'non-changed' data, I can send it.

ludovic 2010-11-04 23:39 administrator ~0001708	I've done multiple tests, with and w/o attendees and it works for me. Do you still have the error message above?

2010-11-05 08:42	7317-4CD3C280-7-74122880.ics (939 bytes) BEGIN:VCALENDAR VERSION:2.0 PRODID:-//Inverse inc./SOGo 1.0//EN BEGIN:VEVENT UID:7317-4CD3C280-7-74122880 SUMMARY:email test CREATED:20101105T083835Z DTSTAMP:20101105T083835Z LAST-MODIFIED:20101105T083835Z BEGIN:VALARM TRIGGER;RELATED=START;VALUE=DURATION:-PT20M ACTION:EMAIL ATTENDEE;CN=Willi Brune:mailto:wbrune@cotrans.de SUMMARY:email test END:VALARM DTSTART;TZID=/inverse.ca/20101018_1/Europe/Berlin:20101105T100000 DTEND;TZID=/inverse.ca/20101018_1/Europe/Berlin:20101105T110000 TRANSP:OPAQUE END:VEVENT BEGIN:VTIMEZONE TZID:/inverse.ca/20101018_1/Europe/Berlin X-LIC-LOCATION:Europe/Berlin BEGIN:DAYLIGHT TZOFFSETFROM:+0100 TZOFFSETTO:+0200 TZNAME:CEST DTSTART:19700329T020000 RRULE:FREQ=YEARLY;BYMONTH=3;BYDAY=-1SU END:DAYLIGHT BEGIN:STANDARD TZOFFSETFROM:+0200 TZOFFSETTO:+0100 TZNAME:CET DTSTART:19701025T030000 RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=-1SU END:STANDARD END:VTIMEZONE END:VCALENDAR 7317-4CD3C280-7-74122880.ics (939 bytes)

wbrune 2010-11-05 08:46 reporter ~0001709	i created an event at 10:00 and set an email alarm 20 minutes before. this is the resulting error Nov 05 09:40:01 sogo-ealarms-notify [32109]: [ERROR] <0x0x6e0b480[SOGoEMailAlarmsManager]> alarm number mismatch for record: {c_alarm_number = 0; c_name = "7317-4CD3C280-7-74122880.ics"; c_path = "/Users/wbrune/Calendar/personal"; c_recurrence_id = 310639115; c_uid = "7317-4CD3C280-7-74122880"; } the corresponding ics file is attached.

wimmer 2010-11-05 09:12 reporter ~0001710	I tried it with last mtn and it works for me now, but I'm not sure if perfectly. It means - message is sended, it included name of the event in Subject, but its body is empty. Or is it OK? sogo-ealarms-notify writes: Nov 05 09:07:01 sogo-ealarms-notify [20126]: <0x0xbc87b0[SOGoCache]> Cache cleanup interval set every 300.000000 seconds Nov 05 09:07:01 sogo-ealarms-notify [20126]: <0x0xbc87b0[SOGoCache]> Using host(s) 'localhost' as server(s) Nov 05 09:07:01 sogo-ealarms-notify [20126]: <0x0xcba8f0[NGSendMail]> wrote 1, length 350 I attached 2 files: mail.txt is output of 'defaults read sogod \| grep -i mail' strace.txt is output of 'strace /usr/local/sbin/sogo-ealarms-notify' I can send standard mails from that machine via local postfix without problem. I tried to change "SOGoMailingMechanism smtp" - the same result - Notification is send with empty body.

2010-11-05 09:12	mail.txt (460 bytes) sogod SOGoMailMessageCheck every_5_minutes sogod OCSEMailAlarmsFolderURL postgresql://sogo:sogo@localhost:5432/sogo/sogo_alarms_folder sogod SOGoMailSpoolPath /var/spool/sogo sogod SOGoMailingMechanism sendmail sogod SOGoACLsSendEMailNotifications NO sogod SOGoLoginModule Mail IMAPHostFieldName = mailHost; sogod SOGoEnableEMailAlarms YES sogod SOGoFoldersSendEMailNotifications NO sogod SOGoMailDomain zcu.cz sogod SOGoAppointmentSendEMailNotifications YES mail.txt (460 bytes)

2010-11-05 09:12	strace.txt (6,848 bytes) open("/usr/local/lib/GNUstep/SOGo/libSOGoNSUserDefaults.so.1", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/local/lib/GNUstep/SOGo/SOGo.framework/Versions/1/Resources", {st_mode=S_IFDIR\|0755, st_size=81, ...}) = 0 access("/usr/local/lib/GNUstep/SOGo/SOGo.framework/Versions/1/Resources", R_OK) = 0 access("/usr/local/lib/GNUstep/SOGo/SOGo.framework/Versions/1/Resources/SOGoDefaults.plist", R_OK) = 0 stat("/usr/local/lib/GNUstep/SOGo/SOGo.framework/Versions/1/Resources/SOGoDefaults.plist", {st_mode=S_IFREG\|0644, st_size=2085, ...}) = 0 open("/usr/local/lib/GNUstep/SOGo/SOGo.framework/Versions/1/Resources/SOGoDefaults.plist", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG\|0644, st_size=2085, ...}) = 0 mmap(NULL, 4096, PROT_READ\|PROT_WRITE, MAP_PRIVATE\|MAP_ANONYMOUS, -1, 0) = 0x7f68f666f000 fstat(6, {st_mode=S_IFREG\|0644, st_size=2085, ...}) = 0 lseek(6, 0, SEEK_SET) = 0 read(6, "{\n WOWorkersCount = 1;\n Sx"..., 2085) = 2085 lseek(6, 2085, SEEK_SET) = 2085 close(6) = 0 munmap(0x7f68f666f000, 4096) = 0 gettimeofday({1288946889, 705256}, NULL) = 0 write(2, "Nov 05 09:48:09 sogo-ealarms-not"..., 119Nov 05 09:48:09 sogo-ealarms-notify [2192]: <0x0xeb0030[SOGoCache]> Cache cleanup interval set every 300.000000 seconds) = 119 write(2, "\n", 1 ) = 1 gettimeofday({1288946889, 705413}, NULL) = 0 write(2, "Nov 05 09:48:09 sogo-ealarms-not"..., 106Nov 05 09:48:09 sogo-ealarms-notify [2192]: <0x0xeb0030[SOGoCache]> Using host(s) 'localhost' as server(s)) = 106 write(2, "\n", 1 ) = 1 brk(0xf2f000) = 0xf2f000 socket(PF_NETLINK, SOCK_RAW, 0) = 6 bind(6, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0 getsockname(6, {sa_family=AF_NETLINK, pid=2192, groups=00000000}, [12]) = 0 time(NULL) = 1288946889 sendto(6, "\24\0\0\0\26\0\1\3\311\304\323L\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20 recvmsg(6, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"0\0\0\0\24\0\2\0\311\304\323L\220\10\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 108 recvmsg(6, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\311\304\323L\220\10\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 128 recvmsg(6, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\311\304\323L\220\10\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20 close(6) = 0 stat("/etc/resolv.conf", {st_mode=S_IFREG\|0644, st_size=39, ...}) = 0 open("/etc/resolv.conf", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG\|0644, st_size=39, ...}) = 0 mmap(NULL, 4096, PROT_READ\|PROT_WRITE, MAP_PRIVATE\|MAP_ANONYMOUS, -1, 0) = 0x7f68f666f000 read(6, "search zcu.cz\nnameserver 147.228"..., 4096) = 39 read(6, "", 4096) = 0 close(6) = 0 munmap(0x7f68f666f000, 4096) = 0 open("/etc/hosts", O_RDONLY\|O_CLOEXEC) = 6 fstat(6, {st_mode=S_IFREG\|0644, st_size=276, ...}) = 0 mmap(NULL, 4096, PROT_READ\|PROT_WRITE, MAP_PRIVATE\|MAP_ANONYMOUS, -1, 0) = 0x7f68f666f000 read(6, "127.0.0.1\tlocalhost\n147.228.52.3"..., 4096) = 276 read(6, "", 4096) = 0 close(6) = 0 munmap(0x7f68f666f000, 4096) = 0 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6 connect(6, {sa_family=AF_INET, sin_port=htons(11211), sin_addr=inet_addr("127.0.0.1")}, 16) = 0 getsockname(6, {sa_family=AF_INET, sin_port=htons(34515), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0 close(6) = 0 socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 6 connect(6, {sa_family=AF_INET6, sin6_port=htons(11211), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = 0 getsockname(6, {sa_family=AF_INET6, sin6_port=htons(38814), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0 close(6) = 0 socket(PF_INET6, SOCK_STREAM, IPPROTO_TCP) = 6 fcntl(6, F_GETFL) = 0x2 (flags O_RDWR) fcntl(6, F_SETFL, O_RDWR\|O_NONBLOCK) = 0 connect(6, {sa_family=AF_INET6, sin6_port=htons(11211), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress) poll([{fd=6, events=POLLOUT}], 1, -1) = 1 ([{fd=6, revents=POLLOUT}]) write(6, "get harryp+attributes \r\n", 24) = 24 read(6, 0xf0a390, 8196) = -1 EAGAIN (Resource temporarily unavailable) poll([{fd=6, events=POLLIN}], 1, -1) = 1 ([{fd=6, revents=POLLIN}]) read(6, "VALUE harryp+attributes 0 177\r\n{"..., 8196) = 215 gettimeofday({1288946889, 711737}, NULL) = 0 gettimeofday({1288946889, 711778}, NULL) = 0 brk(0xf50000) = 0xf50000 write(6, "get harryp+defaults \r\n", 22) = 22 read(6, "VALUE harryp+defaults 0 1436\r\n{\""..., 8196) = 1473 write(6, "get harryp+settings \r\n", 22) = 22 read(6, "VALUE harryp+settings 0 503\r\n{\"M"..., 8196) = 539 gettimeofday({1288946889, 712514}, NULL) = 0 gettimeofday({1288946889, 712552}, NULL) = 0 uname({sys="Linux", node="webmail3", ...}) = 0 stat("/etc/resolv.conf", {st_mode=S_IFREG\|0644, st_size=39, ...}) = 0 stat("/etc/resolv.conf", {st_mode=S_IFREG\|0644, st_size=39, ...}) = 0 open("/etc/hosts", O_RDONLY\|O_CLOEXEC) = 7 fstat(7, {st_mode=S_IFREG\|0644, st_size=276, ...}) = 0 mmap(NULL, 4096, PROT_READ\|PROT_WRITE, MAP_PRIVATE\|MAP_ANONYMOUS, -1, 0) = 0x7f68f666f000 read(7, "127.0.0.1\tlocalhost\n147.228.52.3"..., 4096) = 276 read(7, "", 4096) = 0 close(7) = 0 munmap(0x7f68f666f000, 4096) = 0 brk(0xf71000) = 0xf71000 access("/usr/lib/sendmail", X_OK) = 0 pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID\|CLONE_CHILD_SETTID\|SIGCHLD, child_tidptr=0x7f68f66929d0) = 2194 close(7) = 0 fcntl(8, F_SETFD, 0) = 0 fstat(8, {st_mode=S_IFIFO\|0600, st_size=0, ...}) = 0 mmap(NULL, 4096, PROT_READ\|PROT_WRITE, MAP_PRIVATE\|MAP_ANONYMOUS, -1, 0) = 0x7f68f666f000 gettimeofday({1288946889, 715054}, NULL) = 0 write(2, "Nov 05 09:48:09 sogo-ealarms-not"..., 88Nov 05 09:48:09 sogo-ealarms-notify [2192]: <0x0xf60220[NGSendMail]> wrote 1, length 350) = 88 write(2, "\n", 1 ) = 1 write(8, "Date: Fri, 05 Nov 2010 09:48:09 "..., 350) = 350 close(8) = 0 wait4(2194, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 2194 --- SIGCHLD (Child exited) @ 0 (0) --- strace.txt (6,848 bytes)

ludovic 2010-11-05 11:31 administrator ~0001712	The empty body is expected for now.

wimmer 2010-11-05 12:13 reporter ~0001713	ok - then it works for me in last mtn ;-) I'm sure users would appreciate some body text like: "This is reminder for event 'Title'" "Start time: ..." "Description: ..."

ludovic 2010-11-05 13:16 administrator ~0001714	wbrune, can you try to wipe the entire content of you sogo alarm table and retry? you probably have left-over garbage in it.

wbrune 2010-11-05 13:19 reporter ~0001715	my sogo_alarm_table is empty. the structure should be ok, it was build from sogod 1.3.3. should it work with 1.3.3 or do i need to install a nightly build?

ludovic 2010-11-05 13:29 administrator ~0001716	If you don't mind, testing with a nightly build might be nice.

ludovic 2010-11-06 13:47 administrator ~0001720	Any updates on testing with the latest nightly build?

2010-11-07 11:18	33B9-4CD68900-1-FCD63C0.ics (932 bytes) BEGIN:VCALENDAR VERSION:2.0 PRODID:-//Inverse inc./SOGo 1.0//EN BEGIN:VEVENT UID:33B9-4CD68900-1-FCD63C0 SUMMARY:mailtest CREATED:20101107T111101Z DTSTAMP:20101107T111101Z LAST-MODIFIED:20101107T111144Z DTSTART;TZID=/inverse.ca/20101018_1/Europe/Berlin:20101107T121500 DTEND;TZID=/inverse.ca/20101018_1/Europe/Berlin:20101107T131500 TRANSP:OPAQUE BEGIN:VALARM TRIGGER;RELATED=START;VALUE=DURATION:-PT2M ACTION:EMAIL ATTENDEE;CN=Willi Brune:mailto:wbrune@brune.biz SUMMARY:mailtest END:VALARM END:VEVENT BEGIN:VTIMEZONE TZID:/inverse.ca/20101018_1/Europe/Berlin X-LIC-LOCATION:Europe/Berlin BEGIN:DAYLIGHT TZOFFSETFROM:+0100 TZOFFSETTO:+0200 TZNAME:CEST DTSTART:19700329T020000 RRULE:FREQ=YEARLY;BYMONTH=3;BYDAY=-1SU END:DAYLIGHT BEGIN:STANDARD TZOFFSETFROM:+0200 TZOFFSETTO:+0100 TZNAME:CET DTSTART:19701025T030000 RRULE:FREQ=YEARLY;BYMONTH=10;BYDAY=-1SU END:STANDARD END:VTIMEZONE END:VCALENDAR 33B9-4CD68900-1-FCD63C0.ics (932 bytes)

wbrune 2010-11-07 11:24 reporter ~0001721	nightly (20101106) doesn't work for me. i just uploaded the corresponding 33B9-4CD68900-1-FCD63C0.ics. message from sogo-ealarms-notify: Nov 07 12:13:01 sogo-ealarms-notify [13372]: [ERROR] <0x0x1dc2e4e0[SOGoEMailAlarmsManager]> alarm number mismatch for record: {c_alarm_number = 0; c_name = "33B9-4CD68900-1-FCD63C0.ics"; c_path = "/Users/wbrune/Calendar/personal"; c_recurrence_id = 310821104; c_uid = "33B9-4CD68900-1-FCD63C0"; }

ludovic 2010-11-07 12:53 administrator ~0001722	After you create your event and set an alarm, try to update your alarm table and set c_recurrence_id to 0 Right now, it's set to 310821104 in your last example (and is also non-zero) in others and I'm pretty sure that's the problem. Now, if it works after you set that, I'll dig in the code and try to figure ou why this does happen.

wbrune 2010-11-07 14:14 reporter ~0001723	setting c_recurrentce_id to 0 did it. no error message and i got the expected mail.

ludovic 2010-11-08 16:59 administrator ~0001731	Are you using a 32-bit system?

wbrune 2010-11-08 17:46 reporter ~0001732	centos 5.5 x86_64

ludovic 2010-11-08 18:32 administrator ~0001733	Fixed with http://mtn.inverse.ca/revision/diff/54b01b70fe55f24f29ed00a93826637acb076c5f/with/b35d04c6cd2614e48feea1b1dacb0a61aa27fe44 We're regenerating the nightly builds. They should be available in 1h for testing.

Date Modified	Username	Field	Change
2010-10-24 15:47	wimmer	New Issue
2010-10-24 17:58	wcronen	Note Added: 0001644
2010-10-25 17:29	ludovic	Target Version	=> 1.3.4
2010-10-26 09:12	wbrune	Note Added: 0001656
2010-10-26 10:15	wbrune	Note Edited: 0001656
2010-10-29 19:59	~~wsourdeau~~	Note Added: 0001666
2010-10-29 20:12	wimmer	File Added: event.txt
2010-10-29 20:12	wimmer	File Added: reminder.jpg
2010-10-29 20:13	wimmer	Note Added: 0001667
2010-10-29 20:30	wimmer	Note Added: 0001668
2010-11-04 23:39	ludovic	Note Added: 0001708
2010-11-05 08:42	wbrune	File Added: 7317-4CD3C280-7-74122880.ics
2010-11-05 08:46	wbrune	Note Added: 0001709
2010-11-05 09:12	wimmer	Note Added: 0001710
2010-11-05 09:12	wimmer	File Added: mail.txt
2010-11-05 09:12	wimmer	File Added: strace.txt
2010-11-05 11:31	ludovic	Note Added: 0001712
2010-11-05 12:13	wimmer	Note Added: 0001713
2010-11-05 13:16	ludovic	Note Added: 0001714
2010-11-05 13:19	wbrune	Note Added: 0001715
2010-11-05 13:29	ludovic	Note Added: 0001716
2010-11-06 13:47	ludovic	Note Added: 0001720
2010-11-07 11:18	wbrune	File Added: 33B9-4CD68900-1-FCD63C0.ics
2010-11-07 11:24	wbrune	Note Added: 0001721
2010-11-07 12:53	ludovic	Note Added: 0001722
2010-11-07 14:14	wbrune	Note Added: 0001723
2010-11-08 16:59	ludovic	Note Added: 0001731
2010-11-08 17:46	wbrune	Note Added: 0001732
2010-11-08 18:32	ludovic	Note Added: 0001733
2010-11-08 18:32	ludovic	Status	new => resolved
2010-11-08 18:32	ludovic	Fixed in Version	=> 1.3.4
2010-11-08 18:32	ludovic	Resolution	open => fixed
2010-11-08 18:32	ludovic	Assigned To	=> ludovic

View Issue Details

Activities

Issue History