Help Request: Failing one SQL Injection Test

[WR-Smiley]

Environment

• Commit SHA: b0a8caf
• Operating System: Windows 11 (Git Bash)
• JDK Version: 11
• Node.js Version: 21.7.0
• Firefox / Chrome Version (if applicable): N/A

Intention

Following the setup guide very closely, one test keeps failing and I can't figure out how to resolve it.

The test is 'testSqlInjectionSearchAccountRequestsInWholeSystem.' All other tests succeed. Exception is 0 and time outputs 'teammates.it.storage.sqlapi.AccountRequestsDbIT@257e1ecc'.

Stack trace is below. The first line seems to be the obvious problem but I don't understand why it is running into that problem when I have desktop Docker running and showing all 3 containers running just fine and all other tests have no issues. Any advice would be greatly appreciated, I'm excited to get this sorted so I can actually start contributing to the project. Thank you!

teammates.common.exception.SearchServiceException: Full-text search is not available.
	at teammates.storage.sqlsearch.SearchManager.performQuery(SearchManager.java:74)
	at teammates.storage.sqlsearch.AccountRequestSearchManager.searchAccountRequests(AccountRequestSearchManager.java:55)
	at teammates.storage.sqlapi.AccountRequestsDb.searchAccountRequestsInWholeSystem(AccountRequestsDb.java:162)
	at teammates.it.storage.sqlapi.AccountRequestsDbIT.testSqlInjectionSearchAccountRequestsInWholeSystem(AccountRequestsDbIT.java:204)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.testng.internal.invokers.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:139)
	at org.testng.internal.invokers.TestInvoker.invokeMethod(TestInvoker.java:677)
	at org.testng.internal.invokers.TestInvoker.invokeTestMethod(TestInvoker.java:221)
	at org.testng.internal.invokers.MethodRunner.runInSequence(MethodRunner.java:50)
	at org.testng.internal.invokers.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:962)
	at org.testng.internal.invokers.TestInvoker.invokeTestMethods(TestInvoker.java:194)
	at org.testng.internal.invokers.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:148)
	at org.testng.internal.invokers.TestMethodWorker.run(TestMethodWorker.java:128)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.testng.TestRunner.privateRun(TestRunner.java:806)
	at org.testng.TestRunner.run(TestRunner.java:601)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:433)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:427)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:387)
	at org.testng.SuiteRunner.run(SuiteRunner.java:330)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:95)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1256)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1176)
	at org.testng.TestNG.runSuites(TestNG.java:1099)
	at org.testng.TestNG.run(TestNG.java:1067)
	at org.gradle.api.internal.tasks.testing.testng.TestNGTestClassProcessor.runTests(TestNGTestClassProcessor.java:146)
	at org.gradle.api.internal.tasks.testing.testng.TestNGTestClassProcessor.stop(TestNGTestClassProcessor.java:91)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
	at com.sun.proxy.$Proxy5.stop(Unknown Source)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker$3.run(TestWorker.java:193)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
	at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:133)
	at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:71)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
	at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)

Resolution Attempt

Checking and rechecking that I followed the guide closely and that all components are seemingly up and running. Tested all server responses via browser localhost URLs and got expected behavior.

[weiquu]

Hey @WR-Smiley, can you try pulling the latest changes from master and seeing if that test still fails? If so, could you screenshot your Docker containers as well as what you see on http://localhost:8983? Thanks!

[WR-Smiley]

Hi @weiquu, thanks for your response. I pulled the latest changes, got the front and back end started and still failed the same test. Please see below the requested screenshots. I've also included Solr container's logs below the screenshots.

2024-03-11 09:37:26 RNG might not work properly. To check for the amount of available entropy, use 'cat /proc/sys/kernel/random/entropy_avail'.
2024-03-11 09:37:26 
2024-03-11 09:37:28 Waiting up to 180 seconds to see Solr running on port 8983 [|]  
2024-03-11 09:37:28 Started Solr server on port 8983 (pid=57). Happy searching!
2024-03-11 09:37:28 
2024-03-11 09:WARNING: Using _default configset with data driven schema functionality. NOT RECOMMENDED for production use.
2024-03-11 09:37:28          To turn off: bin/solr config -c students -p 8983 -action set-user-property -property update.autoCreateFields -value false
2024-03-11 09:37:30 
2024-03-11 09:37:30 Created new core 'students'
2024-03-11 09:37:30 
2024-03-11 09:37:30 POSTing request to Config API: http://localhost:8983/solr/students/config
2024-03-11 09:37:30 {"set-user-property":{"update.autoCreateFields":"false"}}
2024-03-11 09:37:30 Successfully set-user-property update.autoCreateFields to false
2024-03-11 09:37:30 {
2024-03-11 09:37:30   "responseHeader":{
2024-03-11 09:37:30     "status":0,
2024-03-11 09:37:30     "QTime":106}}
2024-03-11 09:37:30 {
2024-03-11 09:37:30   "responseHeader":{
2024-03-11 09:37:30     "status":0,
2024-03-11 09:37:30     "QTime":67}}
2024-03-11 09:37:31 WARNING: Using _default configset with data driven schema functionality. NOT RECOMMENDED for production use.
2024-03-11 09:37:31          To turn off: bin/solr config -c instructors -p 8983 -action set-user-property -property update.autoCreateFields -value false
2024-03-11 09:37:31 
2024-03-11 09:37:31 Created new core 'instructors'
2024-03-11 09:37:31 
2024-03-11 09:37:31 POSTing request to Config API: http://localhost:8983/solr/instructors/config
2024-03-11 09:37:31 {"set-user-property":{"update.autoCreateFields":"false"}}
2024-03-11 09:37:32 Successfully set-user-property update.autoCreateFields to false
2024-03-11 09:37:32 {
2024-03-11 09:37:32   "responseHeader":{
2024-03-11 09:37:32     "status":0,
2024-03-11 09:37:32     "QTime":55}}
2024-03-11 09:37:32 {
2024-03-11 09:37:32   "responseHeader":{
2024-03-11 09:37:32     "status":0,
2024-03-11 09:37:32     "QTime":65}}
2024-03-11 09:37:32 WARNING: Using _default configset with data driven schema functionality. NOT RECOMMENDED for production use.
2024-03-11 09:37:32          To turn off: bin/solr config -c accountrequests -p 8983 -action set-user-property -property update.autoCreateFields -value false
2024-03-11 09:37:32 
2024-03-11 09:37:32 Created new core 'accountrequests'
2024-03-11 09:37:33 
2024-03-11 09:37:33 POSTing request to Config API: http://localhost:8983/solr/accountrequests/config
2024-03-11 09:37:33 {"set-user-property":{"update.autoCreateFields":"false"}}
2024-03-11 09:37:33 Successfully set-user-property update.autoCreateFields to false
2024-03-11 09:37:33 {
2024-03-11 09:37:33   "responseHeader":{
2024-03-11 09:37:33     "status":0,
2024-03-11 09:37:33     "QTime":77}}
2024-03-11 09:37:33 {
2024-03-11 09:37:33   "responseHeader":{
2024-03-11 09:37:33     "status":0,
2024-03-11 09:37:33     "QTime":47}}
2024-03-11 09:37:33 2024-03-11 15:37:33.734 INFO  (searcherExecutor-73-thread-1-processing-x:accountrequests) [   x:accountrequests] o.a.s.c.QuerySenderListener QuerySenderListener done.
2024-03-11 09:37:33 2024-03-11 15:37:33.734 INFO  (searcherExecutor-73-thread-1-processing-x:accountrequests) [   x:accountrequests] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
2024-03-11 09:37:33 2024-03-11 15:37:33.735 INFO  (searcherExecutor-73-thread-1-processing-x:accountrequests) [   x:accountrequests] o.a.s.c.SolrCore [accountrequests]  Registered new searcher autowarm time: 0 ms
2024-03-11 09:37:33 2024-03-11 15:37:33.735 INFO  (qtp284686302-47) [   x:accountrequests] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
2024-03-11 09:37:33 2024-03-11 15:37:33.736 INFO  (qtp284686302-47) [   ] o.a.s.c.S.Request [accountrequests]  webapp=/solr path=/schema params={} status=0 QTime=47
2024-03-11 09:37:33 2024-03-11 15:37:33.736 INFO  (qtp284686302-47) [   ] o.a.s.c.SolrCore [accountrequests]  CLOSING SolrCore org.apache.solr.core.SolrCore@1ef6f5ad
2024-03-11 09:37:33 2024-03-11 15:37:33.736 INFO  (qtp284686302-47) [   ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.accountrequests tag=SolrCore@1ef6f5ad
2024-03-11 09:37:33 2024-03-11 15:37:33.736 INFO  (searcherExecutor-73-thread-1-processing-x:accountrequests) [   x:accountrequests] o.a.s.c.QuerySenderListener QuerySenderListener done.
2024-03-11 09:37:33 2024-03-11 15:37:33.736 INFO  (qtp284686302-47) [   ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@73208961: rootName = null, domain = solr.core.accountrequests, service url = null, agent id = null] for registry solr.core.accountrequests/com.codahale.metrics.MetricRegistry@4fa5d023
2024-03-11 09:37:33 2024-03-11 15:37:33.737 INFO  (searcherExecutor-73-thread-1-processing-x:accountrequests) [   x:accountrequests] o.a.s.c.SolrCore [accountrequests]  Registered new searcher autowarm time: 0 ms
2024-03-11 09:38:28 2024-03-11 15:38:28.511 INFO  (qtp284686302-77) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={indexInfo=false&wt=json&_=1710171508389} status=0 QTime=0
2024-03-11 09:38:28 2024-03-11 15:38:28.517 INFO  (qtp284686302-76) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=4
2024-03-11 09:38:28 2024-03-11 15:38:28.525 INFO  (qtp284686302-78) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=4
2024-03-11 09:38:37 2024-03-11 15:38:37.167 INFO  (qtp284686302-34) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={indexInfo=false&wt=json&_=1710171508389} status=0 QTime=0
2024-03-11 09:38:37 2024-03-11 15:38:37.168 INFO  (qtp284686302-78) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/logging params={wt=json&_=1710171517162&since=0} status=0 QTime=1
2024-03-11 09:38:37 2024-03-11 15:38:37.169 INFO  (qtp284686302-76) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=2
2024-03-11 09:38:44 2024-03-11 15:38:44.496 INFO  (qtp284686302-76) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={indexInfo=false&wt=json&_=1710171508389} status=0 QTime=0
2024-03-11 09:38:44 2024-03-11 15:38:44.498 INFO  (qtp284686302-50) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=1
2024-03-11 09:38:44 2024-03-11 15:38:44.502 INFO  (qtp284686302-26) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=1
2024-03-11 09:38:44 2024-03-11 15:38:44.520 INFO  (qtp284686302-28) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/cluster/security/authorization params={wt=json&_=1710171524489} status=0 QTime=0
2024-03-11 09:38:45 2024-03-11 15:38:45.400 INFO  (qtp284686302-76) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={indexInfo=false&wt=json&_=1710171508389} status=0 QTime=0
2024-03-11 09:38:45 2024-03-11 15:38:45.400 INFO  (qtp284686302-28) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/properties params={wt=json&_=1710171525397} status=0 QTime=0
2024-03-11 09:38:45 2024-03-11 15:38:45.402 INFO  (qtp284686302-77) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=1
2024-03-11 09:38:46 2024-03-11 15:38:46.518 INFO  (qtp284686302-77) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={indexInfo=false&wt=json&_=1710171508389} status=0 QTime=0
2024-03-11 09:38:46 2024-03-11 15:38:46.551 INFO  (qtp284686302-26) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=33
2024-03-11 09:38:46 2024-03-11 15:38:46.555 INFO  (qtp284686302-50) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/threads params={wt=json&_=1710171526514} status=0 QTime=37
2024-03-11 09:38:49 2024-03-11 15:38:49.665 INFO  (qtp284686302-50) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={indexInfo=false&wt=json&_=1710171508389} status=0 QTime=0
2024-03-11 09:37:30   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
2024-03-11 09:37:30                                  Dload  Upload   Total   Spent    Left  Speed
100   110  100    57  100    53    508    473 --:--:-- --:--:-- --:--:--   990
2024-03-11 09:37:30   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
2024-03-11 09:37:30                                  Dload  Upload   Total   Spent    Left  Speed
100   106  100    56  100    50    746    666 --:--:-- --:--:-- --:--:--  1394
2024-03-11 09:37:32   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
2024-03-11 09:37:32                                  Dload  Upload   Total   Spent    Left  Speed
100   109  100    56  100    53    949    898 --:--:-- --:--:-- --:--:--  1847
2024-03-11 09:37:32   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
2024-03-11 09:37:32                                  Dload  Upload   Total   Spent    Left  Speed
100   106  100    56  100    50    811    724 --:--:-- --:--:-- --:--:--  1536
2024-03-11 09:37:33   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
2024-03-11 09:37:33                                  Dload  Upload   Total   Spent    Left  Speed
100   106  100    56  100    50    682    609 --:--:-- --:--:-- --:--:--  1292
2024-03-11 09:37:33   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
2024-03-11 09:37:33                                  Dload  Upload   Total   Spent    Left  Speed
100   110  100    56  100    54   1120   1080 --:--:-- --:--:-- --:--:--  2200
2024-03-11 09:38:49 2024-03-11 15:38:49.669 INFO  (qtp284686302-49) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=2
2024-03-11 09:38:49 2024-03-11 15:38:49.673 INFO  (qtp284686302-50) [   ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/info/system params={wt=json&_=1710171508390} status=0 QTime=1```

[wkurniawan07]

@WR-Smiley your error has nothing to do with the Docker instances. Full-text search is not available means the value wasn't set in either build.properties or test.properties, and since this is in the context of integration test, it should be src/it/resources/test.properties.

[WR-Smiley]

I see, thank you for pointing me to the right place. In test.properties I see that test.search.service.host is blank. However, even when I set it to http\://localhost\:8983/solr (how it is set in build.properties) and rerun the tests, it is still failing because full-text search is not available. I apologize if it's an obvious problem that I am screwing up; any idea what the correction would be?

[wkurniawan07]

Closing the discussion as the problem has been identified in #12901