I'm encountering a really weird issue with my Spring boot application(s). I'm working on a microservice app with Eureka/Ribbon for services discovery, the app is a stat generator providing an API for csv upload and linked to a database for data retrieving, comparison and persistency.
The flow that's been buggy is quite simple :
- Check for unprocessed files in the upload directory
- Get the paths of unprocessed files and put them in an array
- For each element of this array convert them from Csv to pojo
- ???
- Get rich
The call is made from an api (tried through postman and browsers) this calls the converter microservice. The converter microservice walks through the upload direct listing each unprocessed file. This list is then used in the same microservice for being processed. At first, the converter calls the data-retriever microservice which returns three list of objects. And then use them to build the pojos based on the csvs.
And here's where the problem appears, this method is executed twice whereas all the others are only executed once.
Csv-uploader microservice (entry endpoint)
@GetMapping("/proxy/csv/process")
public void processProxyCsv(){
logger.info("Called for processing uploaded CSVs");
csvConverterServiceProxy.processPendingCsv();
}
and the used proxy :
@FeignClient(name="bbx-rev-csv-converter")
@RibbonClient(name="bbx-rev-csv-converter")
public interface CsvConverterServiceProxy {
@GetMapping("/csv/process/running")
public String processPendingCsv();
}
So far so good, everything seems to work fine, logs appears only once.
Then we go to the csv-converter microservice where all the magic happens (and the bug too), the entry endpoint called previously :
@GetMapping("/csv/process/running")
public ResponseEntity<String> processPendingCsv() {
HttpHeaders headers = new HttpHeaders();
HttpStatus status = HttpStatus.BAD_REQUEST;
String reason = "Pending...";
logger.info("API call for processing pending CSVs.");
if (fileHandlerService.checkForNonProcessedFiles()) {
logger.info("Check over, returning to entry flow.");
logger.info("file path : " + fileHandlerService.getUploadedFilePath().toString());
csvConverterService.convertAllCsv(fileHandlerService.getUploadedFilePath());
reason = "Processing pending CSVs in progress...";
} else {
reason = "No pending files found.";
}
status = HttpStatus.OK;
return new ResponseEntity<String>(reason, headers, status);
}
From this point, based on logs, this is executed twice.
I've looked through all my code and haven't a two time call or a loop made wrongly for calling this proxy method (or at least didn't found it and truly, I hope I made something silly).
It even got weirder, after a while when all the services are running (after a few minutes) when i call the same endpoint, calls are only made once.
And here are the logs :
First the Csv-uploader logs:
2018-08-09 14:35:17.407 INFO 4588 --- [nio-8000-exec-7] Csv-up-ctrl : Called for processing uploaded CSVs
And the csv-converter logs...
2018-08-09 14:35:17.470 INFO 17280 --- [nio-8006-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet'
2018-08-09 14:35:17.470 INFO 17280 --- [nio-8006-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started
2018-08-09 14:35:17.504 INFO 17280 --- [nio-8006-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 34 ms
2018-08-09 14:35:17.547 INFO 17280 --- [nio-8006-exec-1] Csv converter controller : API call for processing pending CSVs.
2018-08-09 14:35:17.548 INFO 17280 --- [nio-8006-exec-1] File checker service : Checking for unprocessed files ...
2018-08-09 14:35:17.555 INFO 17280 --- [nio-8006-exec-1] File checker service : Found 1 unprocessed files : [test_file.csv]
2018-08-09 14:35:17.555 INFO 17280 --- [nio-8006-exec-1] Csv converter controller : Check over, returning to entry flow.
2018-08-09 14:35:17.555 INFO 17280 --- [nio-8006-exec-1] Csv converter controller : file path : E:\workspace\Blackbox-reversements\csv-uploader\uploads\todo
2018-08-09 14:35:17.555 INFO 17280 --- [nio-8006-exec-1] Csv converter service : convertAllCsv call
2018-08-09 14:35:17.561 INFO 17280 --- [nio-8006-exec-1] s.c.a.AnnotationConfigApplicationContext : Refreshing SpringClientFactory-bbx-rev-ext-data-retriever: startup date [Thu Aug 09 14:35:17 CEST 2018]; parent: org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@7d18bd1a
2018-08-09 14:35:17.659 INFO 17280 --- [nio-8006-exec-1] f.a.AutowiredAnnotationBeanPostProcessor : JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2018-08-09 14:35:18.002 INFO 17280 --- [nio-8006-exec-1] c.netflix.config.ChainedDynamicProperty : Flipping property: bbx-rev-ext-data-retriever.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
2018-08-09 14:35:18.034 INFO 17280 --- [nio-8006-exec-1] c.n.u.concurrent.ShutdownEnabledTimer : Shutdown hook installed for: NFLoadBalancer-PingTimer-bbx-rev-ext-data-retriever
2018-08-09 14:35:18.079 INFO 17280 --- [nio-8006-exec-1] c.netflix.loadbalancer.BaseLoadBalancer : Client: bbx-rev-ext-data-retriever instantiated a LoadBalancer: DynamicServerListLoadBalancer:{NFLoadBalancer:name=bbx-rev-ext-data-retriever,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:null
2018-08-09 14:35:18.090 INFO 17280 --- [nio-8006-exec-1] c.n.l.DynamicServerListLoadBalancer : Using serverListUpdater PollingServerListUpdater
2018-08-09 14:35:18.125 INFO 17280 --- [nio-8006-exec-1] c.netflix.config.ChainedDynamicProperty : Flipping property: bbx-rev-ext-data-retriever.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
2018-08-09 14:35:18.127 INFO 17280 --- [nio-8006-exec-1] c.n.l.DynamicServerListLoadBalancer : DynamicServerListLoadBalancer for client bbx-rev-ext-data-retriever initialized: DynamicServerListLoadBalancer:{NFLoadBalancer:name=bbx-rev-ext-data-retriever,current list of Servers=[192.168.0.130:8036],Load balancer stats=Zone stats: {defaultzone=[Zone:defaultzone; Instance count:1; Active connections count: 0; Circuit breaker tripped count: 0; Active connections per server: 0.0;]
},Server stats: [[Server:192.168.0.130:8036; Zone:defaultZone; Total Requests:0; Successive connection failure:0; Total blackout seconds:0; Last connection made:Thu Jan 01 01:00:00 CET 1970; First connection made: Thu Jan 01 01:00:00 CET 1970; Active Connections:0; total failure count in last (1000) msecs:0; average resp time:0.0; 90 percentile resp time:0.0; 95 percentile resp time:0.0; min resp time:0.0; max resp time:0.0; stddev resp time:0.0]
]}ServerList:org.springframework.cloud.netflix.ribbon.eureka.DomainExtractingServerList@11bc0eb
2018-08-09 14:35:18.414 INFO 17280 --- [nio-8006-exec-5] Csv converter controller : API call for processing pending CSVs.
2018-08-09 14:35:18.414 INFO 17280 --- [nio-8006-exec-5] File checker service : Checking for unprocessed files ...
2018-08-09 14:35:18.415 INFO 17280 --- [nio-8006-exec-5] File checker service : Found 1 unprocessed files : [test_file.csv]
2018-08-09 14:35:18.415 INFO 17280 --- [nio-8006-exec-5] Csv converter controller : Check over, returning to entry flow.
2018-08-09 14:35:18.415 INFO 17280 --- [nio-8006-exec-5] Csv converter controller : file path : E:\workspace\Blackbox-reversements\csv-uploader\uploads\todo
2018-08-09 14:35:18.415 INFO 17280 --- [nio-8006-exec-5] Csv converter service : convertAllCsv call
2018-08-09 14:35:18.989 INFO 17280 --- [nio-8006-exec-5] Csv converter service : CSVs path will go here
2018-08-09 14:35:19.050 INFO 17280 --- [nio-8006-exec-1] Csv converter service : CSVs path will go here
2018-08-09 14:35:19.095 INFO 17280 --- [erListUpdater-0] c.netflix.config.ChainedDynamicProperty : Flipping property: bbx-rev-ext-data-retriever.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
So for not so good. Could it be a configuration issue? I've kept it quite vanilla for my microservices configuration :
For main classes :
@SpringBootApplication
@EnableFeignClients("com.telemaque.blackbox.reversement.csvuploader")
@EnableDiscoveryClient
public class CsvUploaderApplication {...
For the application.properties files :
spring.application.name=bbx-rev-csv-converter
server.port=8006
eureka.client.service-url.default-zone=http://localhost:8761/eureka
and the application.properties for the naming server :
spring.application.name=bbx-rev-naming-server
server.port=8761
eureka.client.register-with-eureka=false
eureka.client.fetch-registry=false
For naming server :
@SpringBootApplication
@EnableEurekaServer
public class NamingServerApplication {...
For proxies :
@FeignClient(name="bbx-rev-ext-data-retriever")
@RibbonClient(name="bbx-rev-ext-data-retriever")
public interface ExternalDataRetrieverProxy {...
I've been looking through here, the eureka git, looked on spring side and still can't figure it out. That's making me crazy, if you have any idea i'd love to hear it!
Thanks a lot for your help!
EDIT : made a few more tests and I've found a weird log in the naming server :
2018-08-09 14:55:08.320 INFO 15068 --- [nio-8761-exec-2] c.n.e.registry.AbstractInstanceRegistry : Registered instance BBX-REV-CSV-CONVERTER/192.168.0.130:bbx-rev-csv-converter:8006 with status UP (replication=false)
2018-08-09 14:55:08.832 INFO 15068 --- [io-8761-exec-10] c.n.e.registry.AbstractInstanceRegistry : Registered instance BBX-REV-CSV-CONVERTER/192.168.0.130:bbx-rev-csv-converter:8006 with status UP (replication=true)
Also when I call the API directly (not through the first microservice) it's correctly executed only once.
