Project

General

Profile

Bug #60501

WARN log PlatformFilteredStatCommand.populateServerMessages:135

Added by Andrea Lanfranchi over 3 years ago. Updated almost 3 years ago.

Status:
Closed
Priority:
Urgent
Assignee:
Alexey Bobyr
Category:
Scalix Webmail (SWA)
Target version:
Start date:
06/15/2016
Due date:
% Done:

0%

Estimated time:
Operation System:
--

Description

On an up-to date Scalix setup I see lot of this log entries in var\opt\scalix\tomcat\logs\scalix-swa.log
Platform is CentOS

2016-06-14 12:02:18,042  WARN [PlatformFilteredStatCommand.populateServerMessages:135] Failed to retrieve filtered UID list from platform. Reverting to IMAP to fetch UID list.
com.scalix.swa.service.PlatformServiceException: Filtered Platform UID list request returned with status: 404. Excpected: 200
    at com.scalix.swa.service.PlatformFilteredStatCommand.populateServerMessages(PlatformFilteredStatCommand.java:132)
    at com.scalix.swa.service.StatCommand.exec(StatCommand.java:127)
    at com.oddpost.server.module.SoapMail.status(SoapMail.java:248)
    at sun.reflect.GeneratedMethodAccessor97.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at com.oddpost.soap.SoapModule.invokeMethod(SoapModule.java:218)
    at com.oddpost.soap.SoapRequestImpl.execute(SoapRequestImpl.java:193)
    at com.oddpost.server.HttpRequestHandler.handleRequest(HttpRequestHandler.java:212)
    at com.oddpost.server.SoapServlet.doPost(SoapServlet.java:46)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:643)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:723)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at com.oddpost.server.filter.HttpConfFilter.doFilter(HttpConfFilter.java:188)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.springframework.web.filter.AbstractRequestLoggingFilter.doFilterInternal(AbstractRequestLoggingFilter.java:214)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at com.scalix.tomcat6.valve.StuckThreadDetectionValve.invoke(StuckThreadDetectionValve.java:191)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:891)
    at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:760)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2290)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)


Files

api-error-001.png View api-error-001.png 124 KB Andrea Lanfranchi, 06/26/2016 09:32 AM

History

#1

Updated by Andrea Lanfranchi over 3 years ago

This causes Webmail to slow down.

#2

Updated by Prakash Nikhar over 3 years ago

Tested on my vm 12.5.2 CentOS Linux release 7.2.1511 (Core), and didn't see this warning in scalix-swa.log, swa speed also fine.

2016-06-23 17:09:24,416  INFO [ContextLoader.initWebApplicationContext:285] Root WebApplicationContext: initialization started
2016-06-23 17:09:24,579  INFO [AbstractApplicationContext.prepareRefresh:510] Refreshing Root WebApplicationContext: startup date [Thu Jun 23 17:09:24 IST 2016]; root of context hierarchy
2016-06-23 17:09:24,722  INFO [XmlBeanDefinitionReader.loadBeanDefinitions:317] Loading XML bean definitions from ServletContext resource [/WEB-INF/applicationContext.xml]
2016-06-23 17:09:25,009  INFO [ContextLoader.initWebApplicationContext:325] Root WebApplicationContext: initialization completed in 589 ms
2016-06-23 17:09:38,613  INFO [AbstractApplicationContext.doClose:862] Closing Root WebApplicationContext: startup date [Thu Jun 23 17:09:24 IST 2016]; root of context hierarchy
2016-06-23 17:12:24,554  INFO [ContextLoader.initWebApplicationContext:285] Root WebApplicationContext: initialization started
2016-06-23 17:12:24,707  INFO [AbstractApplicationContext.prepareRefresh:510] Refreshing Root WebApplicationContext: startup date [Thu Jun 23 17:12:24 IST 2016]; root of context hierarchy
2016-06-23 17:12:24,780  INFO [XmlBeanDefinitionReader.loadBeanDefinitions:317] Loading XML bean definitions from ServletContext resource [/WEB-INF/applicationContext.xml]
2016-06-23 17:12:25,159  INFO [ContextLoader.initWebApplicationContext:325] Root WebApplicationContext: initialization completed in 591 ms
2016-06-23 17:20:14,188  INFO [Strings.addLocales:117] Added locale de_DE
2016-06-23 17:20:14,189  INFO [Strings.addLocales:117] Added locale en_GB
2016-06-23 17:20:14,190  INFO [Strings.addLocales:117] Added locale en_US
2016-06-23 17:20:27,358  INFO [UserInfo.parsePreferences:485] Can't parse preferences: no preferences message
2016-06-23 17:21:29,369  INFO [HttpMethodDirector.executeWithRetry:439] I/O exception (org.apache.commons.httpclient.NoHttpResponseException) caught when processing request: The server sx1252.co72test.com failed to respond
#3

Updated by Alexey Bobyr over 3 years ago

  • Tracker changed from Support to Bug
  • Category changed from 12 to Scalix Webmail (SWA)
  • Assignee changed from SupportGroup to Alexey Bobyr
  • Target version changed from 12.5.2 to 12.7

It happens during concurent mdofiications in mailbox.
webamil (when uses api in settings) sends request with params ?uid=1,2,3,4,5,6,7 but the time it requests it someone else deleted for e.g. email with uid = 3 and that's why you are seeing
this error.

assigning to me + moving to next release I do not think that I will manage provide somefixes which will speed up or fix it.

For now I can tell that in apache httclient that we are using to make requests to api from webmail there was default option to repeat action if it failed.
I don't know why it needed but I have turned off this feature and disabled Retry . So you what see anymore messages in logs 'Retry .....'
This behavior since build 12.6.0.17693. (downloaded into upcoming folder)

It may speed up webmail it wont send request again and will force to resync msgs uids in mailbox to determine what msg was deleted etc etc.

#4

Updated by Andrea Lanfranchi over 3 years ago

  • Priority changed from Normal to Urgent

I think the problem resides in how the api call behaves.
In the environment I am testing I have digged the logs and found that:

  1. In scalix-swa.log you get this error:
    2016-06-24 15:33:12,220  WARN [PlatformFilteredStatCommand.populateServerMessages:135] Failed to retrieve filtered UID list from platform. Reverting to IMAP to fetch UID list.
    com.scalix.swa.service.PlatformServiceException: Filtered Platform UID list request returned with status: 404. Excpected: 200
    
  1. Then you go in /var/log/httpd/access_log and exactly at the same time you get this 404 entries:
    192.168.5.10 - - [24/Jun/2016:15:33:12 +0200] "GET /api/<scalixuser>/mailbox/INBOX?filtered-msg-set=true&sort=date&sort-direction=asc&drain-notifs=true&SDate=20160524000000&set-notification-status=ongoing HTTP/1.1" 404 999 "-" "Scalix Web Access" 
    192.168.5.10 - - [24/Jun/2016:15:33:12 +0200] "GET /api/<scalixuser>/mailbox/INBOX/Giovanna%20Brambilla?filtered-msg-set=true&sort=date&sort-direction=asc&drain-notifs=true&SDate=20160623000000&set-notification-status=ongoing HTTP/1.1" 404 999 "-" "Scalix Web Access" 
    

Now ... the problem is the API call is returning a 404 (not found) error.
404 is an HTTP error stating the URL resource is not found: in this case those two accesses should ALWAYS return a 200 status eventually with an empty content (if there is nothing to display). This means the call has been issued correctly

Reading the API documentation, IMHO, the GET method has an implementation error

GET Retrieves a mailbox item. 
200 - OK
400 - Bad Request
401 - Authentication Failure
404 - Item not found

In this case the 404 error should be thrown ONLY if the URL resource (ie. the container) is not found (like method POST and PUT)

But in a case like this one:

GET /api/<scalixuser>/mailbox/INBOX?filtered-msg-set=true&sort=date&sort-direction=asc&drain-notifs=true&SDate=20160524000000&set-notification-status=ongoing

assuming the user exists and he/she HAS an INBOX folder this call MUST NEVER RETURN 404 (only emtpy content if nothing found)

And here is why the java PlatformFilteredStatCommand.populateServerMessages method EXPECTS a 200 Status Code.

I think this problem has to be addressed to Scalix API team.

#5

Updated by Andrea Lanfranchi over 3 years ago

Alexey Bobyr wrote:

It happens during concurent mdofiications in mailbox.
webamil (when uses api in settings) sends request with params ?uid=1,2,3,4,5,6,7 but the time it requests it someone else deleted for e.g. email with uid = 3 and that's why you are seeing
this error.

This behavior is absolutely wrong : if the call is for request of items 1,2,3,4,5,6,7 and the item 3 has vanished due to somewhere-else-deletion (or maybe even item 1 and 7) then the call CAN NOT return HTTP 404 because this would mean the url resource is not found or, in other words, the container. Instead it MUST RETURN HTTP STATUS 200 with the payload (the content) only of found items (if any). We are querying the CONTENT,not the CONTAINER.

#6

Updated by Andrea Lanfranchi over 3 years ago

Update ... I have issued further testing.

It seems like the API GET on Mailbox returns empty payloads if no item matches the query parameters. Even if only some uids are missing the content is returned accordingly with an HTTP status code 200 Ok !

Doing further searches in the logs I have discovered that the error 404 on GET is ALWAYS preceeded by this call which returns an 500 Error (Internal error)

GET /api/<scalixuser>/mailbox/?folderlistrev=1 HTTP/1.1" 500 1113 "-" "Scalix Web Access

The same call is present several times in the logs with status 200. Only when this call fails then we begin to receive 404 on calls like this one

GET /api/<scalixuser>/mailbox/INBOX?filtered-msg-set=true&sort=date&sort-direction=asc&drain-notifs=true&SDate=20160524000000&set-notification-status=ongoing HTTP/1.1

Using postman I tried to invoke the same failing call on a freshly installed scalix 12.6.0.14885 with one user only (the one being queried) and the result is systematically an error 500 (see attached image)

Could you explain why it fails ?

#7

Updated by Alexey Bobyr over 3 years ago

404 is an HTTP error stating the URL resource is not found: in this case those two accesses should ALWAYS return a > 200 status eventually with an empty content (if there is nothing to display). This means the call has been issued
correctly

since folder name is part of uri /mailbox/{folder}
I can send 404 if I could not determine folder, user not found

from https://tools.ietf.org/html/rfc7231#section-6.5.4

The 404 (Not Found) status code indicates that the origin server did
   not find a current representation for the target resource or is not
   willing to disclose that one exists.  A 404 status code does not
   indicate whether this lack of representation is temporary or
   permanent; the 410 (Gone) status code is preferred over 404 if the
   origin server knows, presumably through some configurable means, that
   the condition is likely to be permanent.

   A 404 response is cacheable by default; i.e., unless otherwise
   indicated by the method definition or explicit cache controls (see
   Section 4.2.2 of [RFC7234]).

I have worked with a lot of api and everything that I can tell send 200 and in response print
error message it's only one method to implement it. there are no strict standards how to implement api.

we can discuss it in separate issue.

for example I prefer following

  GET - 200, non 200 (500 - for error)
  POST - create new entity (returned code  201 Created)
  PUT - update existing entity (response code 202 Accepted)
  DELET - delete entity (response code 204 No Content )

for post POST, PUT, DELETE - can be 404 since you are using unique identifier ...

for work we are using external projects 200 http status code if there was error in response some identifier
(general agreement for all projects.)

etc etc.

there are no right method. everyone choose what better for them.

As for scalix Api - its not my design , so I cannot tell why its implemented in this way.
Everything that I can tell is that api calls has not changed since 11.4.

as for

... ?uid=1,2,3,4,5,6,7 ...

it was assumption based on imap fetching items - imap can respond 'a NO some of the requested messages no longer exist'.
and here need to make some extra actions at api side. Please consider that

a uid fetch 1 ( ....)
....
a OK 
a uid fecth 2 ....
....

will load server with unnecessary queries and it will slow.
for performance need to make calls

a uid fetch 1:5,45,55 ....

but some message can be deleted ...

Anyway long story short.
I have checked 12.6 code and at first look it must not throw 404 for msgs
it will throw 404 if folder not found(maybe was deleted by someone else) and getting message by direct ref
for e.g. /folder_name/{msg_dref}/ .

since folder_name and msg_dref is part of the URI I can use 404 status code in this we are not breaking rfc.

Andrea Lanfranchi wrote:

Update ... I have issued further testing.

It seems like the API GET on Mailbox returns empty payloads if no item matches the query parameters. Even if only some uids are missing the content is returned accordingly with an HTTP status code 200 Ok !

Doing further searches in the logs I have discovered that the error 404 on GET is ALWAYS preceeded by this call which returns an 500 Error (Internal error)
[...]

The same call is present several times in the logs with status 200. Only when this call fails then we begin to receive 404 on calls like this one
[...]

Using postman I tried to invoke the same failing call on a freshly installed scalix 12.6.0.14885 with one user only (the one being queried) and the result is systematically an error 500 (see attached image)

Could you explain why it fails ?

#8

Updated by Alexey Bobyr over 3 years ago

as for

GET /api/<scalixuser>/mailbox/?folderlistrev=1 HTTP/1.1" 500 1113 "-" "Scalix Web Access

SimpleHtmlRenderer does not support rendering this collection.

please add '&output=xml' and then it will work.

again about api (calls/output) lets move into another issue ....
all api was written by former scalix employees for its hard to answer for some questions about api calls...
I don't know how they see fully working api. I have only that we have now.

anyway I can tell using xml as returned formart api is usable e.g. https://github.com/scalix/Chrome-mail-check-extention

chrome extention which uses /api calls and shows notifications about new messages in subscribed folders.

Andrea Lanfranchi wrote:

Update ... I have issued further testing.

It seems like the API GET on Mailbox returns empty payloads if no item matches the query parameters. Even if only some uids are missing the content is returned accordingly with an HTTP status code 200 Ok !

Doing further searches in the logs I have discovered that the error 404 on GET is ALWAYS preceeded by this call which returns an 500 Error (Internal error)
[...]

The same call is present several times in the logs with status 200. Only when this call fails then we begin to receive 404 on calls like this one
[...]

Using postman I tried to invoke the same failing call on a freshly installed scalix 12.6.0.14885 with one user only (the one being queried) and the result is systematically an error 500 (see attached image)

Could you explain why it fails ?

#9

Updated by Andrea Lanfranchi over 3 years ago

Alexey Bobyr wrote:

as for

GET /api/<scalixuser>/mailbox/?folderlistrev=1 HTTP/1.1" 500 1113 "-" "Scalix Web Access

SimpleHtmlRenderer does not support rendering this collection.

please add '&output=xml' and then it will work.

Hi Alex that call is not invoked manually: it's SWA which is invoking this and apparently is braking the things.
I cannot add output=xml as it's SWA itself apparently who invokes this call.

#10

Updated by Alexey Bobyr over 3 years ago

to sum up.
Originally issue for swa and api call to platform (/api)
for now it seems that in 12.6 it should not happen (originally was reported for 12.5.2) .
not closing this issue since I need to check if it really wont happen in a future.
But in 12.6 this WARN in logs must disappear.
for the rest please fill free to create separate issue's and we can talk there about them.

#11

Updated by Alexey Bobyr over 3 years ago

ok I will check it now. maybe some regression.

Andrea Lanfranchi wrote:

Alexey Bobyr wrote:

as for

GET /api/<scalixuser>/mailbox/?folderlistrev=1 HTTP/1.1" 500 1113 "-" "Scalix Web Access

SimpleHtmlRenderer does not support rendering this collection.

please add '&output=xml' and then it will work.

Hi Alex that call is not invoked manually: it's SWA which is invoking this and apparently is braking the things.
I cannot add output=xml as it's SWA itself apparently who invokes this call.

#12

Updated by Alexey Bobyr over 3 years ago

reviewed requests to api from swa .
changes is in scalix-swa_12.6.0.17699.

for each requests added ?output=xml|swa.

Alexey Bobyr wrote:

ok I will check it now. maybe some regression.

Andrea Lanfranchi wrote:

Alexey Bobyr wrote:

as for

GET /api/<scalixuser>/mailbox/?folderlistrev=1 HTTP/1.1" 500 1113 "-" "Scalix Web Access

SimpleHtmlRenderer does not support rendering this collection.

please add '&output=xml' and then it will work.

Hi Alex that call is not invoked manually: it's SWA which is invoking this and apparently is braking the things.
I cannot add output=xml as it's SWA itself apparently who invokes this call.

#13

Updated by Alexey Bobyr almost 3 years ago

  • Status changed from New to Closed

have not seen such error at 2 production servers for a long time. assuming last changes fixed - at least partially.
closing. Please reopen if it still present at your server.

#14

Updated by Alexey Bobyr almost 3 years ago

  • Target version changed from 12.7 to Scalix 12.6

Also available in: Atom PDF