Log slow queries to SQL Database using Log4j2 (JDBC)

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Log slow queries to SQL Database using Log4j2 (JDBC)

Krönert Florian

Hi everyone,

 

For our Solr instance I have the requirement that all queries should be logged, so that we can later on analyze, which search texts were queried most often.

Were using solr 8.3.1 using the official docker image, hosted on Azure.

My approach for implementing this, was now to configure a Slow Request rule of 0ms, so that in fact every request is logged to the slow requests file.

This part works without any issues.

 

However now I need to process these logs.

It would be convenient, if I had those logs already inside a SQL database.

I saw that log4j2 is able to log to a JDBC database, so for me it seemed the easiest way to just add a new appender for JDBC, which also logs the slow requests.

Unfortunately I can’t seem to get the JDBC driver loaded properly. I have the correct jar and the correct driver namespace. I’m sure because I use the same setup for the dataimport handler and it works flawlessly.

 

My log4j2.xml looks like this (removed non-relevant appenders):

<Configuration>

  <Appenders>

    <JDBC name="databaseAppender" tableName="dbo.solr_requestlog">

      <DriverManager connectionString="${jvmrunargs:dataimporter.datasource.url}"

        driverClassName="com.microsoft.sqlserver.jdbc.SQLServerDriver"

        username="${jvmrunargs:dataimporter.datasource.user}"

        password="${jvmrunargs:dataimporter.datasource.password}"

      />

      <Column name="date" isEventTimestamp="true" />

      <Column name="id" pattern="%u{RANDOM}" />

      <Column name="logLevel" pattern="%level" />

      <Column name="logger" pattern="%logger" />

      <Column name="message" pattern="%message" />

      <Column name="exception" pattern="%ex{full}" />

    </JDBC>

  </Appenders>

  <Loggers>

    <AsyncLogger name="org.apache.solr.core.SolrCore.SlowRequest" level="info" additivity="false">

      <AppenderRef ref="databaseAppender"/>

    </AsyncLogger>

  </Loggers>

</Configuration>

 

I have loaded the JDBC driver per core in solrconfig.xml and also “globally” inside solr.xml by adding its containing folder as libDir.

Unforunately log4j2 still can’t find the JDBC driver, I always receive these issues inside the sysout log:

2020-05-25T10:49:08.616562330Z DEBUG StatusLogger Acquiring JDBC connection from jdbc:sqlserver://--redacted--

2020-05-25T10:49:08.618023875Z DEBUG StatusLogger Loading driver class com.microsoft.sqlserver.jdbc.SQLServerDriver

2020-05-25T10:49:08.623000529Z DEBUG StatusLogger Cannot reestablish JDBC connection to FactoryData [connectionSource=jdbc:sqlserver://--redacted--, tableName=dbo.solr_requestlog, columnConfigs=[{ name=date, layout=null, literal=null, timestamp=true }, { name=id, layout=%u{RANDOM}, literal=null, timestamp=false }, { name=logLevel, layout=%level, literal=null, timestamp=false }, { name=logger, layout=%logger, literal=null, timestamp=false }, { name=message, layout=%message, literal=null, timestamp=false }, { name=exception, layout=%ex{full}, literal=null, timestamp=false }], columnMappings=[], immediateFail=false, retry=true, reconnectIntervalMillis=5000, truncateStrings=true]: The DriverManagerConnectionSource could not load the JDBC driver com.microsoft.sqlserver.jdbc.SQLServerDriver: java.lang.ClassNotFoundException: com.microsoft.sqlserver.jdbc.SQLServerDriver

2020-05-25T10:49:08.627598771Z  java.sql.SQLException: The DriverManagerConnectionSource could not load the JDBC driver com.microsoft.sqlserver.jdbc.SQLServerDriver: java.lang.ClassNotFoundException: com.microsoft.sqlserver.jdbc.SQLServerDriver

2020-05-25T10:49:08.628239791Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:203)

2020-05-25T10:49:08.628442097Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:185)

2020-05-25T10:49:08.628637603Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.getConnection(AbstractDriverManagerConnectionSource.java:147)

2020-05-25T10:49:08.628921112Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndPrepare(JdbcDatabaseManager.java:567)

2020-05-25T10:49:08.629127918Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.access$800(JdbcDatabaseManager.java:62)

2020-05-25T10:49:08.629311024Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager$Reconnector.reconnect(JdbcDatabaseManager.java:174)

2020-05-25T10:49:08.629620834Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager$Reconnector.run(JdbcDatabaseManager.java:185)

2020-05-25T10:49:08.629944544Z Caused by: java.lang.ClassNotFoundException: com.microsoft.sqlserver.jdbc.SQLServerDriver

2020-05-25T10:49:08.630181051Z          at java.base/java.net.URLClassLoader.findClass(Unknown Source)

2020-05-25T10:49:08.630374057Z          at java.base/java.lang.ClassLoader.loadClass(Unknown Source)

2020-05-25T10:49:08.630666266Z          at java.base/java.lang.ClassLoader.loadClass(Unknown Source)

2020-05-25T10:49:08.630893073Z          at java.base/java.lang.Class.forName0(Native Method)

2020-05-25T10:49:08.631085879Z          at java.base/java.lang.Class.forName(Unknown Source)

2020-05-25T10:49:08.631652596Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:201)

2020-05-25T10:49:08.631852802Z          ... 6 more

 

Is anyone of you able to point me to the right direction on how I need to load the JDBC driver for log4j2 to grab it up properly?

 

Thanks a lot in advance.

 

Kind Regards,

Florian Krönert
Senior Software Developer


ORBIS AG | Planckstraße 10 | D-88677 Markdorf

Phone: +49 7544 50398 21 | Mobile: +49 162 3065972 | E-Mail: [hidden email]
www.orbis.de


    

Registered Seat: Saarbrücken
Commercial Register Court: Amtsgericht Saarbrücken, HRB 12022
Board of Management: Thomas Gard (Chairman), Michael Jung, Stefan Mailänder, Frank Schmelzer
Chairman of the Supervisory Board: Ulrich Holzer
    

               

 

 

Reply | Threaded
Open this post in threaded view
|

Re: Log slow queries to SQL Database using Log4j2 (JDBC)

Walter Underwood
I would back up and do this a different way, with off-the-shelf parts.

Send the logs to syslog or your favorite log aggregator. From there, configure something that puts them into an ELK stack (Elasticsearch, Logstash, Kibana). A commercial version of this is logz.io <http://logz.io/>.

Traditional relational databases are not designed for time-series data like logs.

Also, do you want your search service to be slow when the SQL database gets slow? That is guaranteed to happen. Writing to logs should be very, very low overhead. Do all of the processing after Solr writes the log line.

wunder
Walter Underwood
[hidden email]
http://observer.wunderwood.org/  (my blog)

> On May 25, 2020, at 3:53 AM, Krönert Florian <[hidden email]> wrote:
>
> Hi everyone,
>  
> For our Solr instance I have the requirement that all queries should be logged, so that we can later on analyze, which search texts were queried most often.
> Were using solr 8.3.1 using the official docker image, hosted on Azure.
> My approach for implementing this, was now to configure a Slow Request rule of 0ms, so that in fact every request is logged to the slow requests file.
> This part works without any issues.
>  
> However now I need to process these logs.
> It would be convenient, if I had those logs already inside a SQL database.
> I saw that log4j2 is able to log to a JDBC database, so for me it seemed the easiest way to just add a new appender for JDBC, which also logs the slow requests.
> Unfortunately I can’t seem to get the JDBC driver loaded properly. I have the correct jar and the correct driver namespace. I’m sure because I use the same setup for the dataimport handler and it works flawlessly.
>  
> My log4j2.xml looks like this (removed non-relevant appenders):
>
> <Configuration>
>   <Appenders>
>     <JDBC name="databaseAppender" tableName="dbo.solr_requestlog">
>       <DriverManager connectionString="${jvmrunargs:dataimporter.datasource.url}"
>         driverClassName="com.microsoft.sqlserver.jdbc.SQLServerDriver"
>         username="${jvmrunargs:dataimporter.datasource.user}"
>         password="${jvmrunargs:dataimporter.datasource.password}"
>       />
>       <Column name="date" isEventTimestamp="true" />
>       <Column name="id" pattern="%u{RANDOM}" />
>       <Column name="logLevel" pattern="%level" />
>       <Column name="logger" pattern="%logger" />
>       <Column name="message" pattern="%message" />
>       <Column name="exception" pattern="%ex{full}" />
>     </JDBC>
>   </Appenders>
>   <Loggers>
>     <AsyncLogger name="org.apache.solr.core.SolrCore.SlowRequest" level="info" additivity="false">
>       <AppenderRef ref="databaseAppender"/>
>     </AsyncLogger>
>   </Loggers>
> </Configuration>
>  
> I have loaded the JDBC driver per core in solrconfig.xml and also “globally” inside solr.xml by adding its containing folder as libDir.
>
> Unforunately log4j2 still can’t find the JDBC driver, I always receive these issues inside the sysout log:
>
>
> 2020-05-25T10:49:08.616562330Z DEBUG StatusLogger Acquiring JDBC connection from jdbc:sqlserver://--redacted-- <sqlserver://--redacted-->
> 2020-05-25T10:49:08.618023875Z DEBUG StatusLogger Loading driver class com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.623000529Z DEBUG StatusLogger Cannot reestablish JDBC connection to FactoryData [connectionSource=jdbc:sqlserver://--redacted-- <sqlserver://--redacted-->, tableName=dbo.solr_requestlog, columnConfigs=[{ name=date, layout=null, literal=null, timestamp=true }, { name=id, layout=%u{RANDOM}, literal=null, timestamp=false }, { name=logLevel, layout=%level, literal=null, timestamp=false }, { name=logger, layout=%logger, literal=null, timestamp=false }, { name=message, layout=%message, literal=null, timestamp=false }, { name=exception, layout=%ex{full}, literal=null, timestamp=false }], columnMappings=[], immediateFail=false, retry=true, reconnectIntervalMillis=5000, truncateStrings=true]: The DriverManagerConnectionSource could not load the JDBC driver com.microsoft.sqlserver.jdbc.SQLServerDriver: java.lang.ClassNotFoundException: com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.627598771Z  java.sql.SQLException: The DriverManagerConnectionSource could not load the JDBC driver com.microsoft.sqlserver.jdbc.SQLServerDriver: java.lang.ClassNotFoundException: com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.628239791Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:203)
>
> 2020-05-25T10:49:08.628442097Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:185)
>
> 2020-05-25T10:49:08.628637603Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.getConnection(AbstractDriverManagerConnectionSource.java:147)
>
> 2020-05-25T10:49:08.628921112Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndPrepare(JdbcDatabaseManager.java:567)
>
> 2020-05-25T10:49:08.629127918Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.access$800(JdbcDatabaseManager.java:62)
>
> 2020-05-25T10:49:08.629311024Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager$Reconnector.reconnect(JdbcDatabaseManager.java:174)
>
> 2020-05-25T10:49:08.629620834Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager$Reconnector.run(JdbcDatabaseManager.java:185)
>
> 2020-05-25T10:49:08.629944544Z Caused by: java.lang.ClassNotFoundException: com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.630181051Z          at java.base/java.net.URLClassLoader.findClass(Unknown Source)
>
> 2020-05-25T10:49:08.630374057Z          at java.base/java.lang.ClassLoader.loadClass(Unknown Source)
>
> 2020-05-25T10:49:08.630666266Z          at java.base/java.lang.ClassLoader.loadClass(Unknown Source)
>
> 2020-05-25T10:49:08.630893073Z          at java.base/java.lang.Class.forName0(Native Method)
>
> 2020-05-25T10:49:08.631085879Z          at java.base/java.lang.Class.forName(Unknown Source)
>
> 2020-05-25T10:49:08.631652596Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:201)
>
> 2020-05-25T10:49:08.631852802Z          ... 6 more
>
>  
>
> Is anyone of you able to point me to the right direction on how I need to load the JDBC driver for log4j2 to grab it up properly?
>
>  
>
> Thanks a lot in advance.
>
>  
>
> Kind Regards,
>
> Florian Krönert
> Senior Software Developer
>
>  <https://www.orbis.de/de.html>
> ORBIS AG | Planckstraße 10 | D-88677 Markdorf
> Phone: +49 7544 50398 21 | Mobile: +49 162 3065972 | E-Mail: [hidden email] <mailto:[hidden email]>
> www.orbis.de <http://www.orbis.de/>
>
>  <https://www.orbis.de/de/sap-by-orbis.html>    
>
> Registered Seat: Saarbrücken
> Commercial Register Court: Amtsgericht Saarbrücken, HRB 12022
> Board of Management: Thomas Gard (Chairman), Michael Jung, Stefan Mailänder, Frank Schmelzer
> Chairman of the Supervisory Board: Ulrich Holzer    
>  <https://www.facebook.com/ORBIS.AG>    <https://www.linkedin.com/company/orbis-ag/>    <https://www.xing.com/companies/orbisag>    <https://twitter.com/ORBIS_AG>    <https://www.youtube.com/channel/UC5Fx5UsUy4FkzB0dfCWXwYw/featured>  
>  
>  <https://www.orbis.de/de/aktuelles/news/aktuelle-presse/news-detail/article/inner-circle-award-orbis-zaehlt-erneut-zu-den-weltbesten-partnern-fuer-microsoft-business-application.html>
Reply | Threaded
Open this post in threaded view
|

RE: Log slow queries to SQL Database using Log4j2 (JDBC)

Krönert Florian
Hi Walter,

thanks for your response.
That sounds like a feasible approach, although I would like to keep the stack as small as possible.

But the direction that you pointed out seems promising, the JDBC issues with log4j2 don't seem to lead anywhere.

Kind Regards,
Florian

-----Original Message-----
From: Walter Underwood <[hidden email]>
Sent: Dienstag, 26. Mai 2020 02:06
To: [hidden email]
Subject: Re: Log slow queries to SQL Database using Log4j2 (JDBC)

I would back up and do this a different way, with off-the-shelf parts.

Send the logs to syslog or your favorite log aggregator. From there, configure something that puts them into an ELK stack (Elasticsearch, Logstash, Kibana). A commercial version of this is logz.io <http://logz.io/>.

Traditional relational databases are not designed for time-series data like logs.

Also, do you want your search service to be slow when the SQL database gets slow? That is guaranteed to happen. Writing to logs should be very, very low overhead. Do all of the processing after Solr writes the log line.

wunder
Walter Underwood
[hidden email]
http://observer.wunderwood.org/  (my blog)

> On May 25, 2020, at 3:53 AM, Krönert Florian <[hidden email]> wrote:
>
> Hi everyone,
>
> For our Solr instance I have the requirement that all queries should be logged, so that we can later on analyze, which search texts were queried most often.
> Were using solr 8.3.1 using the official docker image, hosted on Azure.
> My approach for implementing this, was now to configure a Slow Request rule of 0ms, so that in fact every request is logged to the slow requests file.
> This part works without any issues.
>
> However now I need to process these logs.
> It would be convenient, if I had those logs already inside a SQL database.
> I saw that log4j2 is able to log to a JDBC database, so for me it seemed the easiest way to just add a new appender for JDBC, which also logs the slow requests.
> Unfortunately I can’t seem to get the JDBC driver loaded properly. I have the correct jar and the correct driver namespace. I’m sure because I use the same setup for the dataimport handler and it works flawlessly.
>
> My log4j2.xml looks like this (removed non-relevant appenders):
>
> <Configuration>
>   <Appenders>
>     <JDBC name="databaseAppender" tableName="dbo.solr_requestlog">
>       <DriverManager connectionString="${jvmrunargs:dataimporter.datasource.url}"
>         driverClassName="com.microsoft.sqlserver.jdbc.SQLServerDriver"
>         username="${jvmrunargs:dataimporter.datasource.user}"
>         password="${jvmrunargs:dataimporter.datasource.password}"
>       />
>       <Column name="date" isEventTimestamp="true" />
>       <Column name="id" pattern="%u{RANDOM}" />
>       <Column name="logLevel" pattern="%level" />
>       <Column name="logger" pattern="%logger" />
>       <Column name="message" pattern="%message" />
>       <Column name="exception" pattern="%ex{full}" />
>     </JDBC>
>   </Appenders>
>   <Loggers>
>     <AsyncLogger name="org.apache.solr.core.SolrCore.SlowRequest" level="info" additivity="false">
>       <AppenderRef ref="databaseAppender"/>
>     </AsyncLogger>
>   </Loggers>
> </Configuration>
>
> I have loaded the JDBC driver per core in solrconfig.xml and also “globally” inside solr.xml by adding its containing folder as libDir.
>
> Unforunately log4j2 still can’t find the JDBC driver, I always receive these issues inside the sysout log:
>
>
> 2020-05-25T10:49:08.616562330Z DEBUG StatusLogger Acquiring JDBC
> connection from jdbc:sqlserver://--redacted--
> <sqlserver://--redacted--> 2020-05-25T10:49:08.618023875Z DEBUG
> StatusLogger Loading driver class
> com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.623000529Z DEBUG StatusLogger Cannot reestablish
> JDBC connection to FactoryData
> [connectionSource=jdbc:sqlserver://--redacted--
> <sqlserver://--redacted-->, tableName=dbo.solr_requestlog,
> columnConfigs=[{ name=date, layout=null, literal=null, timestamp=true
> }, { name=id, layout=%u{RANDOM}, literal=null, timestamp=false }, {
> name=logLevel, layout=%level, literal=null, timestamp=false }, {
> name=logger, layout=%logger, literal=null, timestamp=false }, {
> name=message, layout=%message, literal=null, timestamp=false }, {
> name=exception, layout=%ex{full}, literal=null, timestamp=false }],
> columnMappings=[], immediateFail=false, retry=true,
> reconnectIntervalMillis=5000, truncateStrings=true]: The
> DriverManagerConnectionSource could not load the JDBC driver
> com.microsoft.sqlserver.jdbc.SQLServerDriver:
> java.lang.ClassNotFoundException:
> com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.627598771Z  java.sql.SQLException: The
> DriverManagerConnectionSource could not load the JDBC driver
> com.microsoft.sqlserver.jdbc.SQLServerDriver:
> java.lang.ClassNotFoundException:
> com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.628239791Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:203)
>
> 2020-05-25T10:49:08.628442097Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:185)
>
> 2020-05-25T10:49:08.628637603Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.getConnection(AbstractDriverManagerConnectionSource.java:147)
>
> 2020-05-25T10:49:08.628921112Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.connectAndPrepare(JdbcDatabaseManager.java:567)
>
> 2020-05-25T10:49:08.629127918Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager.access$800(JdbcDatabaseManager.java:62)
>
> 2020-05-25T10:49:08.629311024Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager$Reconnector.reconnect(JdbcDatabaseManager.java:174)
>
> 2020-05-25T10:49:08.629620834Z          at org.apache.logging.log4j.core.appender.db.jdbc.JdbcDatabaseManager$Reconnector.run(JdbcDatabaseManager.java:185)
>
> 2020-05-25T10:49:08.629944544Z Caused by:
> java.lang.ClassNotFoundException:
> com.microsoft.sqlserver.jdbc.SQLServerDriver
>
> 2020-05-25T10:49:08.630181051Z          at java.base/java.net.URLClassLoader.findClass(Unknown Source)
>
> 2020-05-25T10:49:08.630374057Z          at java.base/java.lang.ClassLoader.loadClass(Unknown Source)
>
> 2020-05-25T10:49:08.630666266Z          at java.base/java.lang.ClassLoader.loadClass(Unknown Source)
>
> 2020-05-25T10:49:08.630893073Z          at java.base/java.lang.Class.forName0(Native Method)
>
> 2020-05-25T10:49:08.631085879Z          at java.base/java.lang.Class.forName(Unknown Source)
>
> 2020-05-25T10:49:08.631652596Z          at org.apache.logging.log4j.core.appender.db.jdbc.AbstractDriverManagerConnectionSource.loadDriver(AbstractDriverManagerConnectionSource.java:201)
>
> 2020-05-25T10:49:08.631852802Z          ... 6 more
>
>
>
> Is anyone of you able to point me to the right direction on how I need to load the JDBC driver for log4j2 to grab it up properly?
>
>
>
> Thanks a lot in advance.
>
>
>
> Kind Regards,
>
> Florian Krönert
> Senior Software Developer
>
>  <https://www.orbis.de/de.html>
> ORBIS AG | Planckstraße 10 | D-88677 Markdorf
> Phone: +49 7544 50398 21 | Mobile: +49 162 3065972 | E-Mail:
> [hidden email] <mailto:[hidden email]>
> www.orbis.de <http://www.orbis.de/>
>
>  <https://www.orbis.de/de/sap-by-orbis.html>
>
> Registered Seat: Saarbrücken
> Commercial Register Court: Amtsgericht Saarbrücken, HRB 12022 Board of
> Management: Thomas Gard (Chairman), Michael Jung, Stefan Mailänder, Frank Schmelzer
> Chairman of the Supervisory Board: Ulrich Holzer
>  <https://www.facebook.com/ORBIS.AG>    <https://www.linkedin.com/company/orbis-ag/>    <https://www.xing.com/companies/orbisag>    <https://twitter.com/ORBIS_AG>    <https://www.youtube.com/channel/UC5Fx5UsUy4FkzB0dfCWXwYw/featured>
>
>
> <https://www.orbis.de/de/aktuelles/news/aktuelle-presse/news-detail/ar
> ticle/inner-circle-award-orbis-zaehlt-erneut-zu-den-weltbesten-partner
> n-fuer-microsoft-business-application.html>