Quantcast

Email Validation: stuck in 'prepare_success' status

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Email Validation: stuck in 'prepare_success' status

rez_spb
Hello,

The issue is that registration emails are not sent by XWiki, they get stuck in 'prepare_success' status (seen in "Administration: Mail Sending Status"). No errors. Even in MySQL 'mail_errorDescription' and 'mail_errorSummary' fields.
Similar issue was asked some time ago by another user but with no resolution.

Some additional info:
I have a fresh install of XWiki Enterprise 8.4.4 under Apache Tomcat 7.0.73 (Oracle Java 1.8.0_112-b15) with MySQL 5.5 under Debian Wheezy.
Enterprise Flavor, no other addons or extensions were installed.
I have set some internal logging to TRACE level while trying to understand the underlying reason. Filtered logging by 'mail' and enabled all 13 loggers. Still not that much useful info in logs.

I am pretty sure that email is configured properly (I can send page as an email to myself using current SMTP setup and I receive it all right). Logs:
2017-02-22 12:17:45,141 [http://<myinstallsite>/bin/get/Main/?xpage=shareinline] INFO  c.x.x.p.m.MailSenderPlugin     - Sending email: From [=?UTF-8?Q?Admin?= <donotreply@email.address>], To [my@own.email], Subject [Admin wants to share a document with you], Text [Hello, ...
2017-02-22 12:17:46,589 [http://<myinstallsite>/bin/get/Main/?xpage=shareinline] INFO  c.x.x.p.m.MailSenderPlugin     - sendEmails: Email count = 1 sentcount = 1

Logs look different when user is registering:
2017-02-22 12:33:37,822 [Mail Prepare Thread] DEBUG o.x.m.i.DatabaseMailListener   - Mail preparation begins for batch [a0852104-5b1b-463e-8eaa-b2f50c0d8e51].
2017-02-22 12:33:37,827 [Mail Prepare Thread] DEBUG o.x.m.i.DatabaseMailListener   - Mail preparation succeed for message [IVe2Wc97pVgGuX5ZWSGMczu14jA=]of batch [a0852104-5b1b-463e-8eaa-b2f50c0d8e51].
2017-02-22 12:33:37,942 [Mail Prepare Thread] DEBUG o.x.m.i.DatabaseMailListener   - Mail preparation ended for batch [a0852104-5b1b-463e-8eaa-b2f50c0d8e51].
2017-02-22 13:31:10,982 [Mail Prepare Thread] DEBUG o.x.m.i.DatabaseMailListener   - Mail preparation begins for batch [1ed9eb61-70cd-4dfe-aa65-3dd237175e44].
2017-02-22 13:31:10,983 [Mail Prepare Thread] DEBUG o.x.m.i.DatabaseMailListener   - Mail preparation succeed for message [ijXYRc8u3cVK4VzPMvbNuGvhkb0=]of batch [1ed9eb61-70cd-4dfe-aa65-3dd237175e44].
2017-02-22 13:31:11,058 [Mail Prepare Thread] DEBUG o.x.m.i.DatabaseMailListener   - Mail preparation ended for batch [1ed9eb61-70cd-4dfe-aa65-3dd237175e44].

And that's it. These messages won't be sent, ever. 'Resend' button in admin panel does not help either.

Please advise.
Also I can change almost everything as this is my personal dedicated server, and I hope we can resolve this issue.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Email Validation: stuck in 'prepare_success' status

vmassol
Administrator
Hi Rez,

> On 22 Feb 2017, at 12:10, rez_spb <[hidden email]> wrote:
>
> Hello,
>
> The issue is that registration emails are not sent by XWiki, they get stuck
> in 'prepare_success' status (seen in "Administration: Mail Sending Status").
> No errors. Even in MySQL 'mail_errorDescription' and 'mail_errorSummary'
> fields.
> Similar issue was  asked some time ago
> <http://xwiki.475771.n2.nabble.com/Help-configuring-Email-Sending-for-User-verification-tp7599610p7599671.html>  
> by another user but with no resolution.
>
> Some additional info:
> I have a fresh install of XWiki Enterprise 8.4.4 under Apache Tomcat 7.0.73
> (Oracle Java 1.8.0_112-b15) with MySQL 5.5 under Debian Wheezy.
> Enterprise Flavor, no other addons or extensions were installed.
> I have set some internal logging to TRACE level while trying to understand
> the underlying reason. Filtered logging by 'mail' and enabled all 13
> loggers. Still not that much useful info in logs.
>
> I am pretty sure that email is configured properly (I can send page as an
> email to myself using current SMTP setup and I receive it all right). Logs:
>
>
> Logs look different when user is registering:
>
>
> And that's it. These messages won't be sent, ever. 'Resend' button in admin
> panel does not help either.
>
> Please advise.
> Also I can change almost everything as this is my personal dedicated server,
> and I hope we can resolve this issue.

I’m interested in resolving this issue. I’m on the devs who coded this mail component. I’ve never experienced your problem though so we need to find a way so that I can reproduce it (or understand the problem but that’s going to be hard).

So the way it works is that there are 2 threads running:
- prepare thread: its goal is to serialise the messages to be sent on disk. This allows to resend if the mail fails or if XWiki is restarted. It also put the mail to be sent on the send thread queue
- send thread: send the mails put on its queue.

It’s as if the send thread is not noticing that there are mails to be sent.

So we’d need to check if the Send thread is alive. I guess you could check that by sending a SIGQUIT to the JVM and checking the thread dump to find the Mail Sending Thread.

One thing you could test is to use the memory listener instead of the DB listener for the mail (so that the mail is sent directly). That’ll confirm that everything is working. You can use the following example:

http://extensions.xwiki.org/xwiki/bin/view/Extension/Mail+Sender+API#HExample1:Sendasimpletextemail

(Adjust the “to” to point to your mail)

Thanks
-Vincent

> --
> View this message in context: http://xwiki.475771.n2.nabble.com/Email-Validation-stuck-in-prepare-success-status-tp7602814.html
> Sent from the XWiki- Users mailing list archive at Nabble.com.

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Email Validation: stuck in 'prepare_success' status

rez_spb
Thank you for responding! I was away from my PC for quite a long time, could not investigate fully.

First of all, I have watched the video and checked that programming rights are fine for my Admin user. the default behavior is to check for them, and the user have them, so everything is OK.
Then I set 'discard success statuses' option to explicit 'No' in admin panel.
Next, I have taken a sample, changed $services.mailsender.createMessage() parameters to reflect actual email before adding a page.
I did try to create a velocity test email page with memory listener, but... the page did not finish loading after I clicked 'Save and View'. It was actually created, and email was prepared (log excerpt below), but email was neither sent nor displayed in Mail Sending Status (the latter is expected as we bypass DB here).

2017-02-27 15:13:43,588 [Mail Prepare Thread] DEBUG o.x.m.i.MemoryMailListener     - Mail preparation begins for batch [2dd97882-7232-4067-8486-28655c125e5b].
2017-02-27 15:13:43,600 [Mail Prepare Thread] DEBUG o.x.m.i.MemoryMailListener     - Mail preparation succeed for message [to9yhlh3ZOyFcQ4gAl5em8rrr+g=]of batch [2dd97882-7232-4067-8486-28655c125e5b].
2017-02-27 15:13:43,600 [Mail Prepare Thread] DEBUG o.x.m.i.MemoryMailListener     - Mail preparation ended for batch [2dd97882-7232-4067-8486-28655c125e5b].

Of course, no email was received and I cannot open my velocity test page due to infinite loading.

I have created a thread dump for you to look at, maybe that will help: http://pastebin.com/TeBcZrUV
Several email-related threads are in WAITING and TIMED_WAITING statuses.
The testing page is called 'email-velocity-memory' for faster debugging.

If there's anything else I can help with, please let me know.
Oh, and you will see AJP connector thread: I use 'mod_jk' to proxy Tomcat through Apache, and the Tomcat serves 2 XWikis as 2 different services. I have separated them fine (I think), but I can email you configs in case my setup is too custom and was not tested before.

Thanks for all your help!
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Email Validation: stuck in 'prepare_success' status

rez_spb
In reply to this post by vmassol
This is a kind reminder. Did you by any chance have time to look at this issue?
I have provided some info on Feb, 27th and can provide something else, but for now the issue exists and I cannot understand what's wrong here.
Please tell me how can I assist in fixing this.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Email Validation: stuck in 'prepare_success' status

vmassol
Administrator
In reply to this post by rez_spb
Hi Rez,

> On 27 Feb 2017, at 13:44, rez_spb <[hidden email]> wrote:
>
> Thank you for responding! I was away from my PC for quite a long time, could
> not investigate fully.
>
> First of all, I have watched the video and checked that programming rights
> are fine for my Admin user. the default behavior is to check for them, and
> the user have them, so everything is OK.
> Then I set 'discard success statuses' option to explicit 'No' in admin
> panel.
> Next, I have taken a sample, changed $services.mailsender.createMessage()
> parameters to reflect actual email before adding a page.
> I did try to create a velocity test email page with memory listener, but...
> the page did not finish loading after I clicked 'Save and View'. It was
> actually created, and email was prepared (log excerpt below), but email was
> neither sent nor displayed in Mail Sending Status (the latter is expected as
> we bypass DB here).
>
>
>
> Of course, no email was received and I cannot open my velocity test page due
> to infinite loading.
>
> I have created a thread dump for you to look at, maybe that will help:
> http://pastebin.com/TeBcZrUV
> Several email-related threads are in WAITING and TIMED_WAITING statuses.
> The testing page is called 'email-velocity-memory' for faster debugging.

I see 8 threads that correspond to executing your page with the mail sending test. I believe you tried to refresh this page 8 times, correct?

I also see a share page thread. Note that the share page by email feature is using the old mail sender plugin and not the new mail module so the config is different and they’re completely different (and there’s no notion of mail prepare and mail sending, the mail is sent directly).

Actually that’s a question I have for you: does share page by email work for you?

Maybe make sure that the SMTP server that you configure is visible from your xwiki instance because it looks as if it cannot be reached and it doesn’t seem to timeout.

Ok here’s something to try. Enable debug logs for the mail module. This can be done at runtime in the Admin UI, Logs section, or by stopping XWiki, editing WEB-INF/classes/logback.xml and adding:

<logger name=“org.xwiki.mail" level=“debug”/>

Then restart XWiki and send us the results of what appears in catalina.out.

You should see messages such as:
- Mail preparation begins for batch [{}].
- Mail preparation succeed for message [{}] of batch [{}].
- Mail preparation ended for batch [{}].
- etc

Thanks
-Vincent

> If there's anything else I can help with, please let me know.
> Oh, and you will see AJP connector thread: I use 'mod_jk' to proxy Tomcat
> through Apache, and the Tomcat serves 2 XWikis as 2 different services. I
> have separated them fine (I think), but I can email you configs in case my
> setup is too custom and was not tested before.
>
> Thanks for all your help!
>
>
>
> --
> View this message in context: http://xwiki.475771.n2.nabble.com/Email-Validation-stuck-in-prepare-success-status-tp7602814p7602869.html
> Sent from the XWiki- Users mailing list archive at Nabble.com.

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Email Validation: stuck in 'prepare_success' status

rez_spb
Thank you for reply!
Sorry for the delay, but the actual results have changed for me since last time.

Actually I have already enabled debug loglevel for mail before posting in this thread (tried to resolve this myself), I saw the lines you posted as an example in logs, but there were only preparation stage, no sending events at all.
Sharing by email works with external SMTP server (have actually tested it this way first when set up SMTP, and the validation email issue was caught later when users started to register).

I have shut down tomcat, removed catalina.out file to get a clean one.
My steps:
 - start tomcat and wait till cpu load drops (that's how I tell that tomcat startup has completed without using logs);
 - open XWiki main page (XWiki initialization starts);
 - send email by sharing (old working sender plugin) - email is received;
 - wait a minute;
 - open the page with velocity I've created previously (like you told me to, using 'memory' storage);
 - wait for some time, check email: 1 email from share link, 2... wait, two emails from 'email-velocity-memory' page.
That is strange: I haven't changed anything, but the email was sent this time. Twice.
Now to testing email validation.
 - open registration page in other browser;
 - register a new user;
 - (new) registration successful page appears (previously that was an infinite load);
 - (new) email is received.

I have an idea: the other XWiki I have installed (2 XWiki on 2 separate containers in 1 Tomcat with 2 webapp directories, I will call the first installed XWiki-0, that one does not have SMTP and sends via localhost) was not initialized (but usually is). So I will redo the same steps with starting that XWiki first (maybe there's no separation of email threads?).
I stop tomcat at this point and pack the log for you (link is below).

Steps this time:
 - start tomcat and wait till cpu load drops (that's how I tell that tomcat startup has completed without using logs);
 - open previously installed XWiki-0 main page (initialize it first);
 - share page by email - email is received;
 - create a velocity page (no such page was set up in XWiki-0);
 - 2 emails are received;
 - open XWiki main page (XWiki initialization starts);
   (there are 2 warnings in logs this time:
2017-03-14 11:45:17,486 [http://xwiki_location_here/bin/view/Main/] WARN  m.i.DefaultJMXBeanRegistration - Failed to register resource with name [type=Velocity,domain=Engines,name=default]. Reason = [InstanceAlreadyExistsException: org.xwiki:type=Velocity,domain=Engines,name=default]
2017-03-14 11:45:28,583 [XWiki Scheduler initialization] WARN  m.i.DefaultJMXBeanRegistration - Failed to register resource with name [type=Velocity,domain=Engines,name=/skins/flamingo/macros.vm]. Reason = [InstanceAlreadyExistsException: org.xwiki:type=Velocity,domain=Engines,name=/skins/flamingo/macros.vm]
)
 - send email by sharing (old working sender plugin) - email is received;
 - wait a minute;
 - open the page with velocity - email is received (2 emails);
 - register a new user - registration successful, email is received.
I stop my tomcat at this point and pack the log for you (link is below).

Well so there is no actual interference between 2 XWiki installation when talking about email (2 warnings are present though and I don't think that's a good thing actually).

Currently everything works. I don't know why, I was sure it wouldn't work.
The only thing that can matter is that server uptime is 6 days (had a blackout last week, so the server was rebooted automatically). Previous restart was like months ago (before XWiki installation). So maybe services/containers restarts are not enough to successfully finish the installation? Reboot is needed? This is a Debian box so that's pretty strange of an idea for me, but there was nothing else.

Log files:
First run (single XWiki)
Second run (XWiki-0 + XWiki)

I will leave this set up as it is, because the issue may reappear and I don't get that was the cause of it yet. If you have any ideas, I am ready to perform more tests to get this fixed for other people who may have the same issue.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Email Validation: stuck in 'prepare_success' status

vmassol
Administrator
Ok thanks for the heads up. Let’s wait till you get it again (hopefully not ;)).

I’d still like to understand how it can happen and whether there’s a bug somewhere… but not easy to track down…

Thanks
-Vincent

> On 14 Mar 2017, at 10:14, rez_spb <[hidden email]> wrote:
>
> Thank you for reply!
> Sorry for the delay, but the actual results have changed for me since last
> time.
>
> Actually I have already enabled debug loglevel for mail before posting in
> this thread (tried to resolve this myself), I saw the lines you posted as an
> example in logs, but there were only preparation stage, no sending events at
> all.
> Sharing by email works with external SMTP server (have actually tested it
> this way first when set up SMTP, and the validation email issue was caught
> later when users started to register).
>
> I have shut down tomcat, removed catalina.out file to get a clean one.
> My steps:
> - start tomcat and wait till cpu load drops (that's how I tell that tomcat
> startup has completed without using logs);
> - open XWiki main page (XWiki initialization starts);
> - send email by sharing (old working sender plugin) - email is received;
> - wait a minute;
> - open the page with velocity I've created previously (like you told me to,
> using 'memory' storage);
> - wait for some time, check email: 1 email from share link, 2... wait, two
> emails from 'email-velocity-memory' page.
> /That is strange/: I haven't changed anything, but the email was sent this
> time. Twice.
> Now to testing email validation.
> - open registration page in other browser;
> - register a new user;
> - (*new*) registration successful page appears (previously that was an
> infinite load);
> - (*new*) email is received.
>
> I have an idea: the other XWiki I have installed (2 XWiki on 2 separate
> containers in 1 Tomcat with 2 webapp directories, I will call the first
> installed XWiki-0, that one does not have SMTP and sends via localhost) was
> not initialized (but usually is). So I will redo the same steps with
> starting that XWiki first (maybe there's no separation of email threads?).
> I stop tomcat at this point and pack the log for you (link is below).
>
> Steps this time:
> - start tomcat and wait till cpu load drops (that's how I tell that tomcat
> startup has completed without using logs);
> - open previously installed XWiki-0 main page (initialize it first);
> - share page by email - email is received;
> - create a velocity page (no such page was set up in XWiki-0);
> - 2 emails are received;
> - open XWiki main page (XWiki initialization starts);
>   (there are 2 warnings in logs this time:
> )
> - send email by sharing (old working sender plugin) - email is received;
> - wait a minute;
> - open the page with velocity - email is received (2 emails);
> - register a new user - registration successful, email is received.
> I stop my tomcat at this point and pack the log for you (link is below).
>
> Well so there is no actual interference between 2 XWiki installation when
> talking about email (2 warnings are present though and I don't think that's
> a good thing actually).
>
> Currently *everything works*. I don't know why, I was sure it wouldn't work.
> The only thing that can matter is that server uptime is 6 days (had a
> blackout last week, so the server was rebooted automatically). Previous
> restart was like months ago (before XWiki installation). So maybe
> services/containers restarts are not enough to successfully finish the
> installation? Reboot is needed? This is a Debian box so that's pretty
> strange of an idea for me, but there was nothing else.
>
> Log files:
> First run (single XWiki)
> <http://rez.hopto.org/files/catalina-single_mode.out.gz>  
> Second run (XWiki-0 + XWiki)
> <http://rez.hopto.org/files/catalina-full_mode.out.gz>  
>
> I will leave this set up as it is, because the issue may reappear and I
> don't get that was the cause of it yet. If you have any ideas, I am ready to
> perform more tests to get this fixed for other people who may have the same
> issue.
>
>
>
> --
> View this message in context: http://xwiki.475771.n2.nabble.com/Email-Validation-stuck-in-prepare-success-status-tp7602814p7603082.html
> Sent from the XWiki- Users mailing list archive at Nabble.com.

Loading...