replacer tool filled logs on a Toolforge node
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	• Bstorm
	Jan 7 2020, 10:53 PM

Description

The replacer tool caused a crash on a Toolforge worker node because the log is erroring at such high speed. Please send the logs to a disk rather than STDERR or something. There are limits in place, but this was too fast for them.

I collected a selection of logs in case that is helpful after I stopped the app and recovered the node:

{"log":"\u0009at sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source) ~[na:na]\n","stream":"stdout","time":"2020-01-07T10:07:04.958897751Z"}
{"log":"\u0009at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_232]\n","stream":"stdout","time":"2020-01-07T10:07:04.958902492Z"}
{"log":"\u0009at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_232]\n","stream":"stdout","time":"2020-01-07T10:07:04.958907446Z"}
{"log":"\u0009at org.springframework.data.repository.core.support.RepositoryComposition$RepositoryFragments.invoke(RepositoryComposition.java:377) ~[spring-data-commons-2.0.14.RELEASE.jar!/:2.0.14.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:07:04.958912294Z"}
{"log":"\u0009at org.springframework.data.repository.core.support.RepositoryComposition.invoke(RepositoryComposition.java:200) ~[spring-data-commons-2.0.14.RELEASE.jar!/:2.0.14.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:07:04.958917451Z"}
{"log":"\u0009at org.springframework.data.repository.core.support.RepositoryFactorySupport$ImplementationMethodExecutionInterceptor.invoke(RepositoryFactorySupport.java:641) ~[spring-data-commons-2.0.14.RELEASE.jar!/:2.0.14.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:07:04.958922558Z"}
{"log":"\u0009at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:1{"log":"\u0009at org.mariadb.jdbc.MariaDbPreparedStatementClient.execute(MariaDbPreparedStatementClient.java:150) ~[mariadb-java-client-2.2.6.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:52:17.998025106Z"}
{"log":"\u0009at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeUpdate(MariaDbPreparedStatementClient.java:183) ~[mariadb-java-client-2.2.6.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:52:17.998385691Z"}
{"log":"\u0009at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-2.7.9.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:52:17.998395987Z"}
{"log":"\u0009at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-2.7.9.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:52:17.998401384Z"}
{"log":"\u0009at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175) ~[hibernate-core-5.2.18.Final.jar!/:5.2.18.Final]\n","stream":"stdout","time":"2020-01-07T10:52:17.99840661Z"}
{"log":"\u0009... 96 common frames omitted\n","stream":"stdout","time":"2020-01-07T10:52:17.998412017Z"}
{"log":"Caused by: java.sql.SQLException: Duplicate entry '4421969---0' for key 'same_rep'\n","stream":"stdout","time":"2020-01-07T10:52:17.998416976Z"}
{"log":"Query is: insert into replacement2 (article_id, last_update, position, reviewer, subtype, type) values (?, ?, ?, ?, ?, ?), parameters [4421969,'2020-01-07',0,'system','','']\n","stream":"stdout","time":"2020-01-07T10:52:17.998422064Z"}
{"log":"\u0009at org.mariadb.jdbc.internal.util.LogQueryTool.exceptionWithQuery(LogQueryTool.java:153) ~[mariadb-java-client-2.2.6.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:52:17.998427246Z"}
{"log":"\u0009at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:255) ~[mariadb-java-client-2.2.6.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:52:17.998453189Z"}
{"log":"\u0009at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:209) ~[mariadb-java-client-2.2.6.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:52:17.998460823Z"}
{"log":"\u0009... 101 common frames omitted\n","stream":"stdout","time":"2020-01-07T10:52:17.998466134Z"}
{"log":"\n","stream":"stdout","time":"2020-01-07T10:52:17.998471044Z"}
{"log":"\u001b[2m2020-01-07 10:52:17.997\u001b[0;39m \u001b[31mERROR\u001b[0;39m \u001b[35m6\u001b[0;39m \u001b[2m---\u001b[0;39m \u001b[2m[pool-2-thread-1]\u001b[0;39m \u001b[36mo.h.engine.jdbc.spi.SqlExceptionHelper  \u001b[0;39m \u001b[2m:\u001b[0;39m (conn=49730913) Duplicate entry '4421970---0' for key 'same_rep'\n","stream":"stdout","time":"2020-01-07T10:52:17.998476172Z"}
{"log":"\u001b[2m2020-01-07 10:52:18.052\u001b[0;39m \u001b[31mERROR\u001b[0;39m \u001b[35m6\u001b[0;39m \u001b[2m---\u001b[0;39m \u001b[2m[pool-2-thread-1]\u001b[0;39m \u001b[36mes.bvalero.replacer.dump.DumpHandler    \u001b[0;39m \u001b[2m:\u001b[0;39m Error processing dump page: Ceroctis bailundoana\n","stream":"stdout","time":"2020-01-07T10:52:18.058562493Z"}
{"log":"\n","stream":"stdout","time":"2020-01-07T10:52:18.058637873Z"}
{"log":"org.springframework.dao.DataIntegrityViolationException: could not execute statement; SQL [n/a]; constraint [same_rep]; nested exception is org.hibernate.exception.ConstraintViolationException: could not execute statement\n","stream":"stdout","time":"2020-01-07T10:52:18.058650804Z"}
{"log":"\u0009at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:257) ~[spring-orm-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:52:18.058662812Z"}
{"log":"\u0009at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:223) ~[spring-orm-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:52:18.058673486Z"}
{"log":"\u0009at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(

    {"log":"\u0009at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:255) ~[mariadb-java-client-2.2.6.jar!/:na]\n","stream":"stdout","time":"2020-01-07T10:
07:04.902169985Z"}
{"log":"\u0009at org.mariadb.jdbc.MariaDbPreparedStatementClient.executeInternal(MariaDbPreparedStatementClient.java:209) ~[mariadb-java-client-2.2.6.jar!/:na]\n","stream":"stdout","time":"2020-01-07T
10:07:04.90217513Z"}
{"log":"\u0009... 101 common frames omitted\n","stream":"stdout","time":"2020-01-07T10:07:04.902180108Z"}
{"log":"\n","stream":"stdout","time":"2020-01-07T10:07:04.902189511Z"}
{"log":"\u001b[2m2020-01-07 10:07:04.909\u001b[0;39m \u001b[31mERROR\u001b[0;39m \u001b[35m6\u001b[0;39m \u001b[2m---\u001b[0;39m \u001b[2m[pool-2-thread-1]\u001b[0;39m \u001b[36mo.h.engine.jdbc.spi.S
qlExceptionHelper  \u001b[0;39m \u001b[2m:\u001b[0;39m (conn=49710188) Duplicate entry '4352514---0' for key 'same_rep'\n","stream":"stdout","time":"2020-01-07T10:07:04.910154208Z"}
{"log":"\u001b[2m2020-01-07 10:07:04.923\u001b[0;39m \u001b[31mERROR\u001b[0;39m \u001b[35m6\u001b[0;39m \u001b[2m---\u001b[0;39m \u001b[2m[pool-2-thread-1]\u001b[0;39m \u001b[36mes.bvalero.replacer.d
ump.DumpHandler    \u001b[0;39m \u001b[2m:\u001b[0;39m Error processing dump page: Mil Mi-54\n","stream":"stdout","time":"2020-01-07T10:07:04.924403721Z"}
{"log":"\n","stream":"stdout","time":"2020-01-07T10:07:04.924427469Z"}
{"log":"org.springframework.dao.DataIntegrityViolationException: could not execute statement; SQL [n/a]; constraint [same_rep]; nested exception is org.hibernate.exception.ConstraintViolationException
: could not execute statement\n","stream":"stdout","time":"2020-01-07T10:07:04.924433855Z"}
{"log":"\u0009at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:257) ~[spring-orm-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"std
out","time":"2020-01-07T10:07:04.924443249Z"}
{"log":"\u0009at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:223) ~[spring-orm-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout
","time":"2020-01-07T10:07:04.92444918Z"}
{"log":"\u0009at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:527) ~[spring-orm-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\
n","stream":"stdout","time":"2020-01-07T10:07:04.924465601Z"}
{"log":"\u0009at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61) ~[spring-tx-5.0.13.RELEASE.jar!/:5.0.
13.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:07:04.924471896Z"}
{"log":"\u0009at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242) ~[spring-tx-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":"2020-01-07
T10:07:04.924478212Z"}
{"log":"\u0009at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:153) ~[spring-tx-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]
\n","stream":"stdout","time":"2020-01-07T10:07:04.924483483Z"}
{"log":"\u0009at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) [spring-aop-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":
"2020-01-07T10:07:04.924488747Z"}
{"log":"\u0009at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:135) ~[spring
-data-jpa-2.0.14.RELEASE.jar!/:2.0.14.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:07:04.924494377Z"}
{"log":"\u0009at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) [spring-aop-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":
"2020-01-07T10:07:04.924501509Z"}
{"log":"\u0009at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","tim
e":"2020-01-07T10:07:04.924507191Z"}
{"log":"\u0009at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) [spring-aop-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":
"2020-01-07T10:07:04.924512674Z"}
{"log":"\u0009at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61) ~[spring-data-commons-
2.0.14.RELEASE.jar!/:2.0.14.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:07:04.92451788Z"}
{"log":"\u0009at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) [spring-aop-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":
"2020-01-07T10:07:04.924533862Z"}
{"log":"\u0009at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.0.13.RELEASE.jar!/:5.0.13.RELEASE]\n","stream":"stdout","time":"2020-01-07T10:0
7:04.924540651Z"}
{"log":"\u0009at es.bvalero.replacer.article.$Proxy113.save(Unknown Source) ~[na:2.3.7]\n","stream":"stdout","time":"2020-01-07T10:07:04.924545836Z"}

Please do not restart the service until this is fixed.

Related Objects

Duplicates Merged Here: T242180: "No webservice" error message when using Replacer tool on Spanish Wikipedia

Event Timeline

• Bstorm triaged this task as High priority.Jan 7 2020, 10:53 PM

• Bstorm created this task.

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 7 2020, 10:53 PM

• Bstorm moved this task from Inbox to Watching on the cloud-services-team (Kanban) board.Jan 7 2020, 10:53 PM

Krenair subscribed.Jan 7 2020, 11:09 PM

JJMC89 merged a task: T242180: "No webservice" error message when using Replacer tool on Spanish Wikipedia.Jan 8 2020, 12:22 AM

JJMC89 added subscribers: Agusbou2015, Benjavalero.

Hi all,

I am really sorry about this. I am using Java Spring Boot as a framework for the tool, and the logs are written into rotating files. But I didn't know that logs were also being written into the standard output.

I have fixed it:

https://github.com/benjavalero/replacer/commit/3d04d24501ede5ebda01bf8b60dceafe13b18bd6

Thus no more logs from this tool should be written into the standard output.

I have just restarted the tool. In case the problem persists please let me know.

Thanks!

replacer tool filled logs on a Toolforge nodeClosed, ResolvedPublicActions

Description

Related Objects

Event Timeline

replacer tool filled logs on a Toolforge node
Closed, ResolvedPublic
Actions