all servlets always called twice!

[TB3dock]

We have had this issue since the beginning.

All servlets, no matter how configured, always get run twice, even though they are only called once.  We have the same problem with servlets in wknd, or in our own, completely different project, or in an empty project.

We are hitting the local aem sdk author instance on a mac

e.g this servlet:

(service = { Servlet.class })
@SlingServletPaths(value="/bin/test/2")
@ServiceDescription("Simple Demo Servlet 2")
public class MyServlet extends SlingAllMethodsServlet {
	private static final long serialVersionUID = 1L;
	final static Logger log = LoggerFactory.getLogger(MyServlet.class);
	@Override
	protected void doGet(SlingHttpServletRequest request, SlingHttpServletResponse response) {
		try {
			log.info("doGet() called");
			response.getWriter().println("hello 1");
		} catch (IOException e) {
			e.printStackTrace();
		}
	}
	
	@Override
	protected void doPost(SlingHttpServletRequest request, SlingHttpServletResponse response) {
		try {
			log.info("doPost() called");
			response.getWriter().println("hello 2");
		} catch (IOException e) {
			e.printStackTrace();
		}
	}
}

When called a single time, either via postman, or via browser, we always see two calls run.  See error.log below:

2021-04-21 11:45:29.112 DEBUG [com.xx.core.filters.LoggingFilter] request for /bin/test/2, with selector null
2021-04-21 11:45:29.112 DEBUG [com.xx.core.filters.LoggingFilter] request for /bin/test/2, with selector null
2021-04-21 11:45:29.112 INFO [com.xx.core.servlets.MyServlet] doGet() called
2021-04-21 11:45:29.112 INFO [com.xx.core.servlets.MyServlet] doGet() called

in the access log, we only see one call:

[0:0:0:0:0:0:0:1] - admin 21/Apr/2021:11:51:33 +0200 "GET /bin/test/2 HTTP/1.1" 200 8 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 11_2_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.128 Safari/537.36"

[Asutosh_Jena_]

Hi @TB3dock 

I am tried the same on AEM as Cloud and it seems to be an issue. For me also it's executing twice.

But the same code when I try to run it on AEM 6.5 instance it works perfectly fine and executes only once.

We might need to reach out to Adobe Support and they will need to look into this issue.

Thanks!

[arunpatidar]

It looks like the log messages are getting printed twice but the execution is happening once.

I tried to call a service from servlet that has a static variable as a counter and the counter does not increase twice, only increases once but in logs, there are 2 entries with the same message.

2021-04-21 16:00:13.973 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService STARTED......
2021-04-21 16:00:13.973 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService STARTED......
2021-04-21 16:00:13.973 INFO [com.community.aemlab.core.services.impl.SampleOsgiServiceImpl] SampleOsgiService#getSettings : 3
2021-04-21 16:00:13.973 INFO [com.community.aemlab.core.services.impl.SampleOsgiServiceImpl] SampleOsgiService#getSettings : 3
2021-04-21 16:00:13.973 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService END......
2021-04-21 16:00:13.973 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService END......

2021-04-21 16:03:40.767 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService STARTED......
2021-04-21 16:03:40.767 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService STARTED......
2021-04-21 16:03:40.768 INFO [com.community.aemlab.core.services.impl.SampleOsgiServiceImpl] SampleOsgiService#getSettings : 4
2021-04-21 16:03:40.768 INFO [com.community.aemlab.core.services.impl.SampleOsgiServiceImpl] SampleOsgiService#getSettings : 4
2021-04-21 16:03:40.768 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService END......
2021-04-21 16:03:40.768 INFO [com.community.aemlab.core.servlets.SampleOsgiServlet] sampleOsgiService END......

[Asutosh_Jena_]

That's strange. Log also should not be printed twice!

[TB3dock]

That doesnt seem possible?

[TB3dock]

I have tested this, and my service is called twice from the servlet. So this is not just logging, this is 2 complete calls.

[Nikhil-Kumar]

@TB3dock - Which version of AEM are you using ? I have tested it out on 6.5.5 and it worked fine. I suspect you are using AEMaaCs, raise a day care support ticket if it's an issue with the AEM version.

[TB3dock]

Im using the absolute latest cloud SDK on a mac.

[Jörg_Hoh]

Can you check in the OSGI webconsole under "recent requests", that this request is actually showing up twice? And is this behavior consistent between the SDK and the actual AEM CS instances (in the cloud)?

Logging would be indeed my first assumption, too.

[TB3dock]

The servlet is calling my service twice - so its not just logging, the servlet is being executed twice.  My code wont go onto the actual cloud for some time unfortunately.  In the osgi config stuff, under web console tab, are only 3 options: license, memory usage and system information.  Where do i see recent requests?  The access log only shows a single hit.  There is a sling recent requests, but this is always empty.

[WasilZee]

I have tested the same at my end on AEM cloud(updated the environment) and it works fine :

27.04.2021 09:59:55.445 [cm-p............d] *DEBUG* [127.0.0.1 [1619517595444] GET /libs/granite/core/content/login.html HTTP/1.1] com.ceamcdublinprogram.core.filters.LoggingFilter request for /libs/granite/core/content/login, with selector null

27.04.2021 09:59:58.089 [cm-p............d] *DEBUG* [193.104.215.11 [1619517598088] GET /bin/test/2 HTTP/1.1] com.ceamcdublinprogram.core.filters.LoggingFilter request for /bin/test/2, with selector null

27.04.2021 09:59:58.090 [cm-p............d] *INFO* [193.104.215.11 [1619517598088] GET /bin/test/2 HTTP/1.1] com.ceamcdublinprogram.core.servlets.MyServlet doGet() called

27.04.2021 10:00:00.001 [cm-p............d] *DEBUG* [sling-default-1-Registered Service.4689] com.ceamcdublinprogram.core.schedulers.SimpleScheduledTask SimpleScheduledTask is now running, myParameter=''

Servlet is invoked only once. I followed the logging guidelines as on page[1].

Thanks

Wasil [1]

https://experienceleague.adobe.com/docs/experience-manager-cloud-service/implementing/developing/log...