logfile for reverselookup actions

cookie33 commented 6 years ago

Hi,

Is it possible to implement the following:

A logfile where all queries are being stored. So an logfile with each query which is being done by which user.

An example being:

<originating_ip_address> reverselookup "YYYY-MM-DD HH:MM:SS.152+0200" <succeed_or_not> <time_taken> <username> <query>

123.345.7.89  reverselookup "2018-06-19 00:05:42.152+0200" 1 0ms  21.T12995 URL=www.test.com
123.345.7.89  reverselookup "2018-06-19 00:05:42.152+0200" 1 0ms  21.T12995 21.T12995?URL=www.test.com

originating_ip == where query came from
succeed_or_not
- 1 = OK (authentication Ok and query OK)
- 0 = NOK (authentication OK, but nothing matches)
- 2 = NOK (authentication failure)
time_taken == how long did the query take
username == which user tried to authenticate for the query
query == everything after https://url:port/hrls/handles

This could than be configured in the handlereverselookupservlet.properties

The way described it almost looks and feels as the access file of the handle server.

Greetings

TobiasWeigel commented 6 years ago

Hi Robert, I have looked into the options for implementing this. Logging successful queries is feasible and can be done by adding a dedicated logger call and then configure the details of the log format via log4j.properties.

However, I see no way to log authentication failures because authentication is managed by the HashLoginService and that does not have specific logging options. Would if suffice for you if we limit the log to successful queries (with or without matches, i.e., your succeed_or_not 0 & 1 categirues)?

cookie33 commented 6 years ago

Hi Tobias,

I would expect the following configuration items:

hrls_logging = on|off (default off). Only on if defined and set to on
hrls_log_save_directory = <path>. file will have specific name with date attached.
hrls_log_save_interval = daily|weekly|monthly it should autorotate the logfile

Maybe flush to the logfile as the handle server does every 30 seconds.

We can live with the failures regarding username/password NOT being in the logfile. But please as much info as possible so we can see what happens on the system regarding the hrls reverse lookup servlet.

Now we do not see if anybody uses it, and if it is used how it is used.

TobiasWeigel commented 6 years ago

Implemented with PR #33. Tested locally on test server and it works. Please confirm.

cookie33 commented 6 years ago

We are going to test it. Some remarks though:

The documentation states:

By default, the servlet does not log all queries. This can be enabled by including the following in the config file. The query log will be under the location {HANDLE_SVR}/logs/hrls-requests.log.

logAllQueries = true

These logs will be rotated monthly and no more than 12 logs will be kept. These parameters can be overridden by customizing the log4j2.xml file contained in the war. You can specify a location for your own log4j2.xml file using a java parameter: -Dlog4j.configurationFile=path/to/log4j2.xml

We use a structure where our logfiles are in:

/var/log/handle/handle
/var/log/handle/handle1
/var/log/handle/handle2
....
....

And we use a symbolic link to point to one reverselookupservlet. f.i.:

reverselookupservlet.war -> /opt/reverselookupservlet/reverselookupservlet-1.0.3.war

So we have only one servlet. We would like to be able to specify the settings outside of the war file. Because this would mean in our case that we would need to make a separate servlet.war for each handle instance. It seems easier to do it in the config file.

Or we need to make a symbolic link of:

{HANDLE_SVR}/logs to f.i. /var/log/handle/handle

TobiasWeigel commented 6 years ago

Hello Robert, as written in the readme, you can specify a location for your own log4j2.xml file using a java parameter: -Dlog4j.configurationFile=path/to/log4j2.xml. Of course, you can do this for each Handle server you have differently. The log4j config is very flexible and, among other things, allows to specify explicit paths for the log files. Let me know how the testing goes.

cookie33 commented 6 years ago

The testing is done. I did some tests:

 ./testHrlsCmd.py -t hrls
Test hrls Script
test_ping (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that ping works. ... ok
test_search_handle_by_existing_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001'] returns specific handle. ... ok
test_search_handle_by_existing_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001','HS_ADMIN=*'] returns specific handle. ... ok
test_search_handle_by_existing_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_ADMIN=*','URL=http://www.test_hrls_check.com/000001'] returns specific handle. ... ok
test_search_handle_by_existing_key_value_limit_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*'] returns 1000 handles. ... ok
test_search_handle_by_existing_key_value_limit_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=10000'] returns 10000 handles. ... ok
test_search_handle_by_existing_key_value_limit_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=100000'] returns 100000 handles. ... ok
test_search_handle_by_existing_key_value_limit_4 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=200000'] returns 100000 handles. ... ok
test_search_handle_by_existing_key_value_page_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=0'] returns first 1000 handles. ... ok
test_search_handle_by_existing_key_value_page_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=1'] returns second 1000 handles. ... ok
test_search_handle_by_existing_key_value_page_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=2'] returns third 1000 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=0','limit=10'] returns first 10 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=1','limit=10'] returns second 10 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=10','page=0'] returns first 10 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_4 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=10','page=1'] returns second 10 handles. ... ok
test_search_handle_by_existing_key_value_retrieverecords_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001','retrieverecords=true'] returns all records for that handle. ... ok
test_search_handle_by_existing_key_value_retrieverecords_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/00000*','retrieverecords=true','limit=9'] returns all records for those handles. ... ok
test_search_handle_by_existing_key_value_retrieverecords_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','retrieverecords=true','limit=100000'] returns all records for those handles. ... ok
test_search_handle_by_existing_key_value_retrieverecords_except_hs_seckey_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001','retrieverecords=true'] returns all records for that handle except HS_SECKEY. ... ok
test_search_handle_by_non_existing_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=my_unknown_handle_url'] returns no matching handle. ... ok
test_search_handle_by_non_existing_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=my_unknown_handle_url','HS_ADMIN=*'] returns no matching handle. ... ok
test_search_handle_by_non_existing_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_ADMIN=*','URL=my_unknown_handle_url'] returns no matching handle. ... ok
test_search_handle_by_prefix_existing_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefix','URL=http://www.test_hrls_check.com/*'] returns 1000 handles. ... ok
test_search_handle_by_prefix_existing_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefix;xyz','URL=http://www.test_hrls_check.com/*'] returns 1000 handles. ... ok
test_search_handle_by_prefix_existing_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefixi','URL=http://www.test_hrls_check.com/*'] returns no handles. ... ok
test_search_handle_by_prefix_existing_key_value_4 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefix i','URL=http://www.test_hrls_check.com/*'] returns error. ... ok
test_search_handle_by_prohibited_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_SECKEY=*'] returns specific message. ... ok
test_search_handle_by_prohibited_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_SECKEY=*','URL=*'] returns specific message. ... ok
test_search_handle_by_prohibited_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=*','HS_SECKEY=*'] returns specific message. ... ok

----------------------------------------------------------------------
Ran 29 tests in 13.327s

OK

An the logfile shows:

$ cat hrls-requests.log
15:53:27.191 [qtp1351478315-33] - 1 366ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001
15:53:27.362 [qtp1351478315-34] - 1 1ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&HS_ADMIN=*
15:53:27.402 [qtp1351478315-36] - 1 0ms 841 /hrls/handles?HS_ADMIN=*&URL=http://www.test_hrls_check.com/000001
15:53:27.428 [qtp1351478315-38] - 1 7ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*
15:53:27.639 [qtp1351478315-35] - 1 140ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10000
15:53:28.588 [qtp1351478315-38] - 1 793ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=100000
15:53:29.492 [qtp1351478315-37] - 1 237ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=200000
15:53:30.109 [qtp1351478315-37] - 1 3ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=0
15:53:30.149 [qtp1351478315-38] - 1 4ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=1
15:53:30.189 [qtp1351478315-36] - 1 8ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=2
15:53:30.223 [qtp1351478315-33] - 1 3ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=0&limit=10
15:53:30.248 [qtp1351478315-34] - 1 2ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=1&limit=10
15:53:30.283 [qtp1351478315-37] - 1 14ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10&page=0
15:53:30.314 [qtp1351478315-38] - 1 5ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10&page=1
15:53:30.333 [qtp1351478315-36] - 1 2ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
15:53:30.387 [qtp1351478315-33] - 1 13ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/00000*&retrieverecords=true&limit=9
15:53:33.553 [qtp1351478315-34] - 1 3138ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&retrieverecords=true&limit=100000
15:53:39.467 [qtp1351478315-38] - 1 48ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
15:53:39.501 [qtp1351478315-35] - 0 1ms 841 /hrls/handles?URL=my_unknown_handle_url
15:53:39.527 [qtp1351478315-35] - 0 2ms 841 /hrls/handles?URL=my_unknown_handle_url&HS_ADMIN=*
15:53:39.546 [qtp1351478315-33] - 0 1ms 841 /hrls/handles?HS_ADMIN=*&URL=my_unknown_handle_url
15:53:39.581 [qtp1351478315-34] - 1 5ms 841 /hrls/handles/841?URL=http://www.test_hrls_check.com/*
15:53:39.616 [qtp1351478315-36] - 1 5ms 841 /hrls/handles/841;xyz?URL=http://www.test_hrls_check.com/*
15:53:39.643 [qtp1351478315-38] - 0 1ms 841 /hrls/handles/841i?URL=http://www.test_hrls_check.com/*

Several things:

it already creates an empty file even if the logging is NOT enabled
Is it possible to have the ip address at the beginning which shows where the request came from?
What does the [qtp1351478315-33] mean?
There is no info logged for queries containing special type HS_SECKEY. For Instance:
```
'HS_SECKEY=*'
```

cookie33 commented 6 years ago

Can the parameter: createOnDemand be set to on in the standard log4j2.xml? Than it will only create a file if needed.

If I read the documentation correct I can set my log path as follows:

<RollingFile name="requestsLogger" fileName="/var/log/handle/${env:USER}/hrls-requests.log" filePattern="/var/log/handle/${env:USER}/hrls-requests.log-%d{yyyy-MM-dd}">

Is this correct? And because I set the pattern to yyyy-MM-dd it will rollover on the next day.

TobiasWeigel commented 6 years ago

OK, I've set createOnDemand to true in the last PR. And yes, the RollingFile configuration seems ok to me. It should then rollover each day. You probably want to modify the DefaultRolloverStrategy as well, e.g. set it to 365 to keep a year of log files.

cookie33 commented 6 years ago

I added a PR #35 so it is more in line with the handle naming schema:

/hrls-requests.log
/hrls-requests.log-yyyy-MM

cookie33 commented 6 years ago

Hm,

Although it states:

                <RollingFile name="requestsLogger" fileName="/var/log/handle/${env:USER}/hrls-requests.log" filePattern="/var/log/handle/${env:USER}/hrls-requests.log-%d{yyyyMMdd}" createOnDemand="true">

The hrls-requests.log is created right after startup. Even with createOnDemand="true". And the size is 0.

cookie33 commented 6 years ago

The parameter createOnDemand is present in 2.8 of log4j. I have log4j version 2.5. It does not seem to be present in that version. So it is a version dependancy. But it is explained. Thanks.

TobiasWeigel commented 6 years ago

Ah, thanks for finding out. There is indeed version pinning in pom.xml for 2.5. I'll update this to 2.8.

cookie33 commented 6 years ago

There is an error in the code. During load it states in the handle error.log file:

2018-07-30 10:53:05.626:INFO:oejd.DeploymentManager:Deployable added: /opt/reverselookupservlet/reverselookupservlet-1.0.4.war
2018-07-30 10:53:05.627:INFO:oejw.WebInfConfiguration:Extract jar:file:/opt/reverselookupservlet/reverselookupservlet-1.0.4.war!/ to /home/robertv/etc/hdl_server/webapps-temp/jetty-145.100.3.243-8003-reverselookupservlet-1.0.4.war-_reverselookupservlet-1.0.4-any-/webapp
2018-07-30 10:53:06.707:WARN:oejw.WebAppContext:Failed startup of context o.e.j.w.WebAppContext{/reverselookupservlet-1.0.4,file:/home/robertv/etc/hdl_server/webapps-temp/jetty-145.100.3.243-8003-reverselookupservlet-1.0.4.war-_reverselookupservlet-1.0.4-any-/webapp/},/opt/reverselookupservlet/reverselookupservlet-1.0.4.war
java.lang.IllegalStateException: Duplicate fragment name: log4j for jar:file:/home/robertv/etc/hdl_server/webapps-temp/jetty-145.100.3.243-8003-reverselookupservlet-1.0.4.war-_reverselookupservlet-1.0.4-any-/webapp/WEB-INF/lib/log4j-web-2.5.jar!/META-INF/web-fragment.xml and jar:file:/home/robertv/etc/hdl_server/webapps-temp/jetty-145.100.3.243-8003-reverselookupservlet-1.0.4.war-_reverselookupservlet-1.0.4-any-/webapp/WEB-INF/lib/log4j-web-2.9.1.jar!/META-INF/web-fragment.xml
        at org.eclipse.jetty.webapp.MetaData.addFragment(MetaData.java:253)
        at org.eclipse.jetty.webapp.FragmentConfiguration.findWebFragments(FragmentConfiguration.java:84)
        at org.eclipse.jetty.webapp.FragmentConfiguration.preConfigure(FragmentConfiguration.java:44)
        at org.eclipse.jetty.webapp.WebAppContext.preConfigure(WebAppContext.java:457)
        at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:493)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.bindings.StandardStarter.processBinding(StandardStarter.java:39)
        at org.eclipse.jetty.deploy.AppLifeCycle.runBindings(AppLifeCycle.java:186)
        at org.eclipse.jetty.deploy.DeploymentManager.requestAppGoal(DeploymentManager.java:494)
        at org.eclipse.jetty.deploy.DeploymentManager.addApp(DeploymentManager.java:141)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.fileAdded(ScanningAppProvider.java:145)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider$1.fileAdded(ScanningAppProvider.java:56)
        at org.eclipse.jetty.util.Scanner.reportAddition(Scanner.java:615)
        at org.eclipse.jetty.util.Scanner.reportDifferences(Scanner.java:540)
        at org.eclipse.jetty.util.Scanner.scan(Scanner.java:403)
        at org.eclipse.jetty.util.Scanner.doStart(Scanner.java:337)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.doStart(ScanningAppProvider.java:121)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.DeploymentManager.startAppProvider(DeploymentManager.java:555)
        at org.eclipse.jetty.deploy.DeploymentManager.doStart(DeploymentManager.java:230)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.util.component.AggregateLifeCycle.addBean(AggregateLifeCycle.java:200)
        at net.handle.server.servletcontainer.EmbeddedJetty.startHttpServer(EmbeddedJetty.java:156)
        at net.handle.server.Main.start(Main.java:304)
        at net.handle.server.Main.main(Main.java:123)

All tests also fail.

TobiasWeigel commented 6 years ago

Your war contains two versions of log4j. Try to run mvn clean before compiling and packaging.

cookie33 commented 6 years ago

Should pom.xml be updated for:

        <dependency>
                <groupId>org.apache.logging.log4j</groupId>
                <artifactId>log4j-api</artifactId>
                <version>2.5</version>
        </dependency>

This still mentions 2.5 instead of 2.9.1

cookie33 commented 6 years ago

performed mvn clean and rebuild. Now errors are different:

2018-07-30 11:07:11.579:INFO:oejd.DeploymentManager:Deployable added: /opt/reverselookupservlet/reverselookupservlet-1.0.4.war
2018-07-30 11:07:15.087:WARN:oejuc.AbstractLifeCycle:FAILED org.eclipse.jetty.annotations.ServletContainerInitializerListener@9f48198: java.lang.NoSuchMethodError: org.apache.logging.log4j.util.LoaderUtil.isClassAvailable(Ljava/lang/String;)Z
java.lang.NoSuchMethodError: org.apache.logging.log4j.util.LoaderUtil.isClassAvailable(Ljava/lang/String;)Z
        at org.apache.logging.log4j.core.util.Loader.isClassAvailable(Loader.java:310)
        at org.apache.logging.log4j.web.Log4jWebInitializerImpl.<clinit>(Log4jWebInitializerImpl.java:55)
        at org.apache.logging.log4j.web.WebLoggerContextUtils.getWebLifeCycle(WebLoggerContextUtils.java:83)
        at org.apache.logging.log4j.web.Log4jServletContainerInitializer.onStartup(Log4jServletContainerInitializer.java:56)
        at org.eclipse.jetty.plus.annotation.ContainerInitializer.callStartup(ContainerInitializer.java:106)
        at org.eclipse.jetty.annotations.ServletContainerInitializerListener.doStart(ServletContainerInitializerListener.java:107)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.util.component.AggregateLifeCycle.doStart(AggregateLifeCycle.java:81)
        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:58)
        at org.eclipse.jetty.server.handler.HandlerWrapper.doStart(HandlerWrapper.java:96)
        at org.eclipse.jetty.server.handler.ScopedHandler.doStart(ScopedHandler.java:115)
        at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:763)
        at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:249)
        at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1242)
        at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:717)
        at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:494)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.bindings.StandardStarter.processBinding(StandardStarter.java:39)
        at org.eclipse.jetty.deploy.AppLifeCycle.runBindings(AppLifeCycle.java:186)
        at org.eclipse.jetty.deploy.DeploymentManager.requestAppGoal(DeploymentManager.java:494)
        at org.eclipse.jetty.deploy.DeploymentManager.addApp(DeploymentManager.java:141)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.fileAdded(ScanningAppProvider.java:145)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider$1.fileAdded(ScanningAppProvider.java:56)
        at org.eclipse.jetty.util.Scanner.reportAddition(Scanner.java:615)
        at org.eclipse.jetty.util.Scanner.reportDifferences(Scanner.java:540)
        at org.eclipse.jetty.util.Scanner.scan(Scanner.java:403)
        at org.eclipse.jetty.util.Scanner.doStart(Scanner.java:337)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.doStart(ScanningAppProvider.java:121)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.DeploymentManager.startAppProvider(DeploymentManager.java:555)
        at org.eclipse.jetty.deploy.DeploymentManager.doStart(DeploymentManager.java:230)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.util.component.AggregateLifeCycle.addBean(AggregateLifeCycle.java:200)
        at net.handle.server.servletcontainer.EmbeddedJetty.startHttpServer(EmbeddedJetty.java:156)
        at net.handle.server.Main.start(Main.java:304)
        at net.handle.server.Main.main(Main.java:123)
2018-07-30 11:07:15.088:WARN:oejuc.AbstractLifeCycle:FAILED o.e.j.w.WebAppContext{/hrls,file:/home/robertv/etc/hdl_server/webapps-temp/jetty-145.100.3.243-8003-reverselookupservlet-1.0.4.war-_reverselookupservlet-1.0.4-any-/webapp/},/opt/reverselookupservlet/reverselookupservlet-1.0.4.war: java.lang.NoSuchMethodError: org.apache.logging.log4j.util.LoaderUtil.isClassAvailable(Ljava/lang/String;)Z
java.lang.NoSuchMethodError: org.apache.logging.log4j.util.LoaderUtil.isClassAvailable(Ljava/lang/String;)Z
        at org.apache.logging.log4j.core.util.Loader.isClassAvailable(Loader.java:310)
        at org.apache.logging.log4j.web.Log4jWebInitializerImpl.<clinit>(Log4jWebInitializerImpl.java:55)
        at org.apache.logging.log4j.web.WebLoggerContextUtils.getWebLifeCycle(WebLoggerContextUtils.java:83)
        at org.apache.logging.log4j.web.Log4jServletContainerInitializer.onStartup(Log4jServletContainerInitializer.java:56)
        at org.eclipse.jetty.plus.annotation.ContainerInitializer.callStartup(ContainerInitializer.java:106)
        at org.eclipse.jetty.annotations.ServletContainerInitializerListener.doStart(ServletContainerInitializerListener.java:107)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.util.component.AggregateLifeCycle.doStart(AggregateLifeCycle.java:81)
        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:58)
        at org.eclipse.jetty.server.handler.HandlerWrapper.doStart(HandlerWrapper.java:96)
        at org.eclipse.jetty.server.handler.ScopedHandler.doStart(ScopedHandler.java:115)
        at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:763)
        at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:249)
        at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1242)
        at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:717)
        at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:494)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.bindings.StandardStarter.processBinding(StandardStarter.java:39)
        at org.eclipse.jetty.deploy.AppLifeCycle.runBindings(AppLifeCycle.java:186)
        at org.eclipse.jetty.deploy.DeploymentManager.requestAppGoal(DeploymentManager.java:494)
        at org.eclipse.jetty.deploy.DeploymentManager.addApp(DeploymentManager.java:141)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.fileAdded(ScanningAppProvider.java:145)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider$1.fileAdded(ScanningAppProvider.java:56)
        at org.eclipse.jetty.util.Scanner.reportAddition(Scanner.java:615)
        at org.eclipse.jetty.util.Scanner.reportDifferences(Scanner.java:540)
        at org.eclipse.jetty.util.Scanner.scan(Scanner.java:403)
        at org.eclipse.jetty.util.Scanner.doStart(Scanner.java:337)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.doStart(ScanningAppProvider.java:121)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.DeploymentManager.startAppProvider(DeploymentManager.java:555)
        at org.eclipse.jetty.deploy.DeploymentManager.doStart(DeploymentManager.java:230)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.util.component.AggregateLifeCycle.addBean(AggregateLifeCycle.java:200)
        at net.handle.server.servletcontainer.EmbeddedJetty.startHttpServer(EmbeddedJetty.java:156)
        at net.handle.server.Main.start(Main.java:304)
        at net.handle.server.Main.main(Main.java:123)
2018-07-30 11:07:15.089:WARN:oejd.DeploymentManager:Unable to reach node goal: started
java.lang.NoSuchMethodError: org.apache.logging.log4j.util.LoaderUtil.isClassAvailable(Ljava/lang/String;)Z
        at org.apache.logging.log4j.core.util.Loader.isClassAvailable(Loader.java:310)
        at org.apache.logging.log4j.web.Log4jWebInitializerImpl.<clinit>(Log4jWebInitializerImpl.java:55)
        at org.apache.logging.log4j.web.WebLoggerContextUtils.getWebLifeCycle(WebLoggerContextUtils.java:83)
        at org.apache.logging.log4j.web.Log4jServletContainerInitializer.onStartup(Log4jServletContainerInitializer.java:56)
        at org.eclipse.jetty.plus.annotation.ContainerInitializer.callStartup(ContainerInitializer.java:106)
        at org.eclipse.jetty.annotations.ServletContainerInitializerListener.doStart(ServletContainerInitializerListener.java:107)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.util.component.AggregateLifeCycle.doStart(AggregateLifeCycle.java:81)
        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:58)
        at org.eclipse.jetty.server.handler.HandlerWrapper.doStart(HandlerWrapper.java:96)
        at org.eclipse.jetty.server.handler.ScopedHandler.doStart(ScopedHandler.java:115)
        at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:763)
        at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:249)
        at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1242)
        at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:717)
        at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:494)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.bindings.StandardStarter.processBinding(StandardStarter.java:39)
        at org.eclipse.jetty.deploy.AppLifeCycle.runBindings(AppLifeCycle.java:186)
        at org.eclipse.jetty.deploy.DeploymentManager.requestAppGoal(DeploymentManager.java:494)
        at org.eclipse.jetty.deploy.DeploymentManager.addApp(DeploymentManager.java:141)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.fileAdded(ScanningAppProvider.java:145)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider$1.fileAdded(ScanningAppProvider.java:56)
        at org.eclipse.jetty.util.Scanner.reportAddition(Scanner.java:615)
        at org.eclipse.jetty.util.Scanner.reportDifferences(Scanner.java:540)
        at org.eclipse.jetty.util.Scanner.scan(Scanner.java:403)
        at org.eclipse.jetty.util.Scanner.doStart(Scanner.java:337)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.providers.ScanningAppProvider.doStart(ScanningAppProvider.java:121)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.deploy.DeploymentManager.startAppProvider(DeploymentManager.java:555)
        at org.eclipse.jetty.deploy.DeploymentManager.doStart(DeploymentManager.java:230)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
        at org.eclipse.jetty.util.component.AggregateLifeCycle.addBean(AggregateLifeCycle.java:200)
        at net.handle.server.servletcontainer.EmbeddedJetty.startHttpServer(EmbeddedJetty.java:156)
        at net.handle.server.Main.start(Main.java:304)
        at net.handle.server.Main.main(Main.java:123)

TobiasWeigel commented 6 years ago

Sorry, I indeed overlooked the log4j-api pinning. I've commited a new version. The error after mvn clean could be a side effect. I've gone through a regular clean/compile/war with the commited version and the war runs also OK on our test server.

cookie33 commented 6 years ago

OK. Just tested it myself with 2.9.1 for the log4j-api. Than the tests run fine and starts up properly:

$ ./testHrlsCmd.py -t hrls
Test hrls Script
test_ping (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that ping works. ... ok
test_search_handle_by_existing_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001'] returns specific handle. ... ok
test_search_handle_by_existing_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001','HS_ADMIN=*'] returns specific handle. ... ok
test_search_handle_by_existing_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_ADMIN=*','URL=http://www.test_hrls_check.com/000001'] returns specific handle. ... ok
test_search_handle_by_existing_key_value_limit_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*'] returns 1000 handles. ... ok
test_search_handle_by_existing_key_value_limit_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=10000'] returns 10000 handles. ... ok
test_search_handle_by_existing_key_value_limit_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=100000'] returns 100000 handles. ... ok
test_search_handle_by_existing_key_value_limit_4 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=200000'] returns 100000 handles. ... ok
test_search_handle_by_existing_key_value_page_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=0'] returns first 1000 handles. ... ok
test_search_handle_by_existing_key_value_page_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=1'] returns second 1000 handles. ... ok
test_search_handle_by_existing_key_value_page_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=2'] returns third 1000 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=0','limit=10'] returns first 10 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','page=1','limit=10'] returns second 10 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=10','page=0'] returns first 10 handles. ... ok
test_search_handle_by_existing_key_value_page_and_limit_4 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','limit=10','page=1'] returns second 10 handles. ... ok
test_search_handle_by_existing_key_value_retrieverecords_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001','retrieverecords=true'] returns all records for that handle. ... ok
test_search_handle_by_existing_key_value_retrieverecords_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/00000*','retrieverecords=true','limit=9'] returns all records for those handles. ... ok
test_search_handle_by_existing_key_value_retrieverecords_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/*','retrieverecords=true','limit=100000'] returns all records for those handles. ... ok
test_search_handle_by_existing_key_value_retrieverecords_except_hs_seckey_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=http://www.test_hrls_check.com/000001','retrieverecords=true'] returns all records for that handle except HS_SECKEY. ... ok
test_search_handle_by_non_existing_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=my_unknown_handle_url'] returns no matching handle. ... ok
test_search_handle_by_non_existing_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=my_unknown_handle_url','HS_ADMIN=*'] returns no matching handle. ... ok
test_search_handle_by_non_existing_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_ADMIN=*','URL=my_unknown_handle_url'] returns no matching handle. ... ok
test_search_handle_by_prefix_existing_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefix','URL=http://www.test_hrls_check.com/*'] returns 1000 handles. ... ok
test_search_handle_by_prefix_existing_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefix;xyz','URL=http://www.test_hrls_check.com/*'] returns 1000 handles. ... ok
test_search_handle_by_prefix_existing_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefixi','URL=http://www.test_hrls_check.com/*'] returns no handles. ... ok
test_search_handle_by_prefix_existing_key_value_4 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['prefix i','URL=http://www.test_hrls_check.com/*'] returns error. ... ok
test_search_handle_by_prohibited_key_value_1 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_SECKEY=*'] returns specific message. ... ok
test_search_handle_by_prohibited_key_value_2 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['HS_SECKEY=*','URL=*'] returns specific message. ... ok
test_search_handle_by_prohibited_key_value_3 (testHrlsCmd.hrlsintgtest.HrlsIntegrationTests)
Test that search by ['URL=*','HS_SECKEY=*'] returns specific message. ... ok

----------------------------------------------------------------------
Ran 29 tests in 14.546s

OK

And the output:

$ cat  hrls-requests.log
11:15:45.624 [qtp1351478315-38] - 1 403ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001
11:15:45.818 [qtp1351478315-34] - 1 2ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&HS_ADMIN=*
11:15:45.858 [qtp1351478315-35] - 1 0ms 841 /hrls/handles?HS_ADMIN=*&URL=http://www.test_hrls_check.com/000001
11:15:45.906 [qtp1351478315-33] - 1 10ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*
11:15:46.368 [qtp1351478315-36] - 1 402ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10000
11:15:47.549 [qtp1351478315-33] - 1 989ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=100000
11:15:48.500 [qtp1351478315-35] - 1 239ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=200000
11:15:49.133 [qtp1351478315-35] - 1 5ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=0
11:15:49.163 [qtp1351478315-34] - 1 5ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=1
11:15:49.192 [qtp1351478315-36] - 1 8ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=2
11:15:49.220 [qtp1351478315-37] - 1 2ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=0&limit=10
11:15:49.239 [qtp1351478315-33] - 1 1ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=1&limit=10
11:15:49.267 [qtp1351478315-35] - 1 7ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10&page=0
11:15:49.300 [qtp1351478315-34] - 1 1ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10&page=1
11:15:49.345 [qtp1351478315-36] - 1 14ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
11:15:49.391 [qtp1351478315-37] - 1 3ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/00000*&retrieverecords=true&limit=9
11:15:52.997 [qtp1351478315-33] - 1 3571ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&retrieverecords=true&limit=100000
11:15:58.965 [qtp1351478315-34] - 1 18ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
11:15:59.011 [qtp1351478315-37] - 0 1ms 841 /hrls/handles?URL=my_unknown_handle_url
11:15:59.041 [qtp1351478315-33] - 0 10ms 841 /hrls/handles?URL=my_unknown_handle_url&HS_ADMIN=*
11:15:59.088 [qtp1351478315-34] - 0 0ms 841 /hrls/handles?HS_ADMIN=*&URL=my_unknown_handle_url
11:15:59.144 [qtp1351478315-38] - 1 6ms 841 /hrls/handles/841?URL=http://www.test_hrls_check.com/*
11:15:59.186 [qtp1351478315-36] - 1 3ms 841 /hrls/handles/841;xyz?URL=http://www.test_hrls_check.com/*
11:15:59.221 [qtp1351478315-35] - 0 1ms 841 /hrls/handles/841i?URL=http://www.test_hrls_check.com/*

cookie33 commented 6 years ago

The only problems still left are:

HS_SECKEY is NOT shown in logfile

$ curl -u "username:password" "https://<fqdn>:<port>/hrls/handles?HS_SECKEY=*"
Searching via HS_SECKEY entries is not allowed!

It does NOT show anything in the logfile.

Is it possible to have the ip address at the beginning which shows where the request came from?
What does the [qtp1351478315-33] mean? It is a thread. But can it be the process name?

For the rest it works as designed. createOnDemand now works.

TobiasWeigel commented 6 years ago

OK. The source IP is now included, and the status codes have been extended (0-3, details on the javadoc main page). The process name is trickyer becasue log4j does not have a logging shorthand for this. But instead of the thread name, it now uses the category (%c), which can be customized by including a "serviceName = xyz" in the properties config file. I hope this helps? Changes are in devel / PR #38 but not yet in master.

cookie33 commented 6 years ago

Hi,

I build again using the devel branch. (also shown by git log). But the output stays the same:

$ tail -f hrls-requests.log
14:50:58.810 [qtp1351478315-36] - 1 5ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
14:50:58.840 [qtp1351478315-35] - 1 10ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/00000*&retrieverecords=true&limit=9
14:51:01.451 [qtp1351478315-34] - 1 2589ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&retrieverecords=true&limit=100000
14:51:05.924 [qtp1351478315-36] - 1 24ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
14:51:05.954 [qtp1351478315-36] - 0 4ms 841 /hrls/handles?URL=my_unknown_handle_url
14:51:05.977 [qtp1351478315-37] - 0 1ms 841 /hrls/handles?URL=my_unknown_handle_url&HS_ADMIN=*
14:51:05.995 [qtp1351478315-38] - 0 0ms 841 /hrls/handles?HS_ADMIN=*&URL=my_unknown_handle_url
14:51:06.052 [qtp1351478315-35] - 1 32ms 841 /hrls/handles/841?URL=http://www.test_hrls_check.com/*
14:51:06.073 [qtp1351478315-36] - 1 2ms 841 /hrls/handles/841;xyz?URL=http://www.test_hrls_check.com/*
14:51:06.101 [qtp1351478315-37] - 0 4ms 841 /hrls/handles/841i?URL=http://www.test_hrls_check.com/*

What am I doing wrong?

It was a problem between keyboard and user. The newly build image was stored in the wrong directory.

cookie33 commented 6 years ago

It now works. The test are the same and the output is:

$ cat /tmp/test.txt
15:18:46.725 [requestsLogger.hrlsLookup] - x.y.z.w 1 1ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001
15:18:46.754 [requestsLogger.hrlsLookup] - x.y.z.w 1 1ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&HS_ADMIN=*
15:18:46.777 [requestsLogger.hrlsLookup] - x.y.z.w 1 3ms 841 /hrls/handles?HS_ADMIN=*&URL=http://www.test_hrls_check.com/000001
15:18:46.809 [requestsLogger.hrlsLookup] - x.y.z.w 1 8ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*
15:18:47.105 [requestsLogger.hrlsLookup] - x.y.z.w 1 261ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10000
15:18:48.862 [requestsLogger.hrlsLookup] - x.y.z.w 1 1604ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=100000
15:18:50.091 [requestsLogger.hrlsLookup] - x.y.z.w 1 363ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=200000
15:18:50.552 [requestsLogger.hrlsLookup] - x.y.z.w 1 13ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=0
15:18:50.584 [requestsLogger.hrlsLookup] - x.y.z.w 1 4ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=1
15:18:50.873 [requestsLogger.hrlsLookup] - x.y.z.w 1 263ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=2
15:18:50.897 [requestsLogger.hrlsLookup] - x.y.z.w 1 0ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=0&limit=10
15:18:50.918 [requestsLogger.hrlsLookup] - x.y.z.w 1 2ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&page=1&limit=10
15:18:50.938 [requestsLogger.hrlsLookup] - x.y.z.w 1 0ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10&page=0
15:18:50.958 [requestsLogger.hrlsLookup] - x.y.z.w 1 4ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&limit=10&page=1
15:18:50.983 [requestsLogger.hrlsLookup] - x.y.z.w 1 1ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
15:18:51.010 [requestsLogger.hrlsLookup] - x.y.z.w 1 1ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/00000*&retrieverecords=true&limit=9
15:18:55.177 [requestsLogger.hrlsLookup] - x.y.z.w 1 4147ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/*&retrieverecords=true&limit=100000
15:19:00.007 [requestsLogger.hrlsLookup] - x.y.z.w 1 48ms 841 /hrls/handles?URL=http://www.test_hrls_check.com/000001&retrieverecords=true
15:19:00.056 [requestsLogger.hrlsLookup] - x.y.z.w 0 1ms 841 /hrls/handles?URL=my_unknown_handle_url
15:19:00.085 [requestsLogger.hrlsLookup] - x.y.z.w 0 2ms 841 /hrls/handles?URL=my_unknown_handle_url&HS_ADMIN=*
15:19:00.128 [requestsLogger.hrlsLookup] - x.y.z.w 0 4ms 841 /hrls/handles?HS_ADMIN=*&URL=my_unknown_handle_url
15:19:00.205 [requestsLogger.hrlsLookup] - x.y.z.w 1 42ms 841 /hrls/handles/841?URL=http://www.test_hrls_check.com/*
15:19:00.243 [requestsLogger.hrlsLookup] - x.y.z.w 1 6ms 841 /hrls/handles/841;xyz?URL=http://www.test_hrls_check.com/*
15:19:00.274 [requestsLogger.hrlsLookup] - x.y.z.w 0 0ms 841 /hrls/handles/841i?URL=http://www.test_hrls_check.com/*
15:19:00.330 [requestsLogger.hrlsLookup] - x.y.z.w 2 0ms 841 /hrls/handles?HS_SECKEY=*
15:19:00.363 [requestsLogger.hrlsLookup] - x.y.z.w 2 0ms 841 /hrls/handles?HS_SECKEY=*&URL=*
15:19:00.387 [requestsLogger.hrlsLookup] - x.y.z.w 2 0ms 841 /hrls/handles?URL=*&HS_SECKEY=*

If the serviceName is left empty it will show:

15:22:43.160 [requestsLogger.null] - x.y.z.w 2 0ms 841 /hrls/handles?URL=*&HS_SECKEY=*

I will always show requestsLogger.

cookie33 commented 6 years ago

Thanks. The test are performed OK. We will apply it to our test instances first and than implement them on the running production servers once it is merged in the master branch.

cookie33 commented 6 years ago

Evaluating the output format We noticed that we where something missing. The output is:

15:19:00.387 [requestsLogger.hrlsLookup] - x.y.z.w 2 0ms 841 /hrls/handles?URL=*&HS_SECKEY=*

Can the date be added?

2018-07-31 15:19:00.387 [requestsLogger.hrlsLookup] - x.y.z.w 2 0ms 841 /hrls/handles?URL=*&HS_SECKEY=*

cookie33 commented 6 years ago

The web page: http://logging.apache.org/log4j/2.x/manual/layouts.html

states following:

%d{DEFAULT}                 | 2012-11-02 14:34:02,123
%d{yyyy-MM-dd HH:mm:ss.SSS} | 2012-11-02 14:34:02.123

That would be a good format for me with the date. The DEFAULT would be perfect. I will make a merge request.

cookie33 commented 6 years ago

Pull request is: https://github.com/EUDAT-B2SAFE/B2HANDLE-HRLS/pull/39

EUDAT-B2HANDLE / B2HANDLE-HRLS

logfile for reverselookup actions #31