RuntimeException: Error retrieving messages from database (Incorrect datetime value: '1969-12-31 23:59:59.999' for column '

RuntimeException: Error retrieving messages from database (Incorrect datetime value: '1969-12-31 23:59:59.999' for column '_from' ) (#78)

Wojciech Kapcia (Tigase) opened 2 years ago

[2023-02-27 00:16:31:729] [SEVERE  ] [  in_3-message-archive ] StanzaProcessor.processPacket()  : Error retrieving messages from database when processing from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=message-archive@ip-172-31-38-91.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq id="6N969-46" type="set" xmlns="jabber:client" from="…@sure.im/atalk"><query queryid="WQP2-4IYS-QDI8-C" xmlns="urn:xmpp:mam:2"><x type="submit" xmlns="jabber:x:data"><field var="FORM_TYPE"><value>urn:xmpp:mam:2</value></field><field var="with"><value>…@….im</value></field><field var="start"><value>1969-12-31T23:59:59.999+00:00</value></field></x><set xmlns="http://jabber.org/protocol/rsm"><max>50</max></set></query></iq>, SIZE=444, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set, STABLE_ID=null
java.lang.RuntimeException: Error retrieving messages from database
	at tigase.xmpp.mam.modules.QueryModule.process(QueryModule.java:86)
	at tigase.component.modules.StanzaProcessor.execute(StanzaProcessor.java:219)
	at tigase.component.modules.StanzaProcessor.process(StanzaProcessor.java:206)
	at tigase.component.modules.StanzaProcessor.processPacket(StanzaProcessor.java:103)
	at tigase.component.AbstractKernelBasedComponent.processPacket(AbstractKernelBasedComponent.java:81)
	at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1398)
Caused by: tigase.db.TigaseDBException: Cound not retrieve items
	at tigase.archive.db.JDBCMessageArchiveRepository.queryItems(JDBCMessageArchiveRepository.java:212)
	at tigase.archive.db.JDBCMessageArchiveRepository.queryItems(JDBCMessageArchiveRepository.java:53)
	at jdk.internal.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at tigase.stats.StatisticsInvocationHandler.invoke(StatisticsInvocationHandler.java:75)
	at jdk.proxy2/jdk.proxy2.$Proxy54.queryItems(Unknown Source)
	at tigase.archive.db.MessageArchiveRepositoryPool.queryItems(MessageArchiveRepositoryPool.java:97)
	at tigase.archive.db.MessageArchiveRepositoryPool.queryItems(MessageArchiveRepositoryPool.java:45)
	at tigase.xmpp.mam.modules.QueryModule.process(QueryModule.java:84)
	... 5 more
Caused by: com.mysql.cj.jdbc.exceptions.MysqlDataTruncation: Data truncation: Incorrect datetime value: '1969-12-31 23:59:59.999' for column '_from' at row 1
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:104)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:953)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeQuery(ClientPreparedStatement.java:1009)
	at com.mysql.cj.jdbc.CallableStatement.executeQuery(CallableStatement.java:891)
	at jdk.internal.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at tigase.db.jdbc.PreparedStatementInvocationHandler.invoke(PreparedStatementInvocationHandler.java:38)
	at jdk.proxy2/jdk.proxy2.$Proxy35.executeQuery(Unknown Source)
	at tigase.archive.db.JDBCMessageArchiveRepository.getItemsCount(JDBCMessageArchiveRepository.java:618)
	at tigase.archive.db.JDBCMessageArchiveRepository.queryItems(JDBCMessageArchiveRepository.java:197)
	... 14 more

IMHO a proper IQ error should be returned to user.

Related
- Incorrect datetime value in JDBCMessageArchiveRepository (#67) Closed
- MysqlDataTruncation: Data truncation: Incorrect datetime value: "1969-12-31 16:00:00" (tigase/_server/tigase-muc#130) Closed

Activities

Andrzej Wójcik (Tigase) commented 2 years ago

@wojtek Should we apply the same fix https://projects.tigase.net/issue/muc-130?
Wojciech Kapcia (Tigase) commented 2 years ago

Yes
Andrzej Wójcik (Tigase) commented 2 years ago

I've fixed this issue but it is getting annoying as we already had "almost" the same issue with MySQL #issue #67 but with a difference of 1ms. I've modified previous fix to hopefully fix this, however, I'm not sure why this 1ms offset appeared nor what caused it.
Andrzej Wójcik (Tigase) commented 2 years ago

Fix in separate branch issue #78
Wojciech Kapcia (Tigase) commented 2 years ago

Looks ok, ~~can be merged~~ (could you make a PR in the future as well?). I merged it.

As for the issue - it was sent by the client, so I would say it's a client "bug" of sorts (the timestamp itself is not inherently wrong, but it seems they were aiming at 1970…).
Andrzej Wójcik (Tigase) commented 2 years ago

I'll prepare PRs in the future.
Login to comment

Type	Bug
Priority	Normal
Assignee	Wojciech Kapcia (Tigase)
Version	Candidate for next minor release

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/tigase-message-archiving#78