search

oroinc / crm

Main OroCRM package with core functionality.
Other
647 stars 212 forks source link

oro:message-queue:consume: synchronization failed: ERROR: date/time field value out of range #291

Closed martinvonwittich closed 5 years ago

martinvonwittich commented 6 years ago

I have oro:message-queue:consume set up as a systemd job:

orocrm.iserv.eu ~ # cat /etc/systemd/system/orocrm-consumer.service 
[Unit]
Description=orocrm consume

[Service]
User=www-data
ExecStart=/var/www/orocrm/app/console oro:message-queue:consume --env prod
Restart=always

[Install]
WantedBy=multi-user.target

Unfortunately, it seems like the message consumer crashes when it encounters a certain spam email:

Dec  4 15:49:26 orocrm systemd[1]: Started orocrm consume.
Dec  4 15:49:27 orocrm console[19935]: ERROR: The synchronization failed. Error: An exception occurred while executing 'INSERT INTO oro_email (serialized_data, created, subject, from_name, sent, importance, internaldate, is_head, message_id, multi_message_id, x_message_id, x_thread_id, refs, acceptLanguageHeader, body_synced, thread_id, email_body_id, from_email_address_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)' with params ["Tjs=", "2017-12-04 14:49:27", "firstname.lastname Your Electricity Bill 3426$, Please check out the file.", "firstname.lastname@iserv.eu", "0000-03-28 18:26:59", 1, "2016-03-23 12:27:20", 1, "<000101d18531$96344e62$c0a80001@directwifi.com.br>", null, "", "", null, "", null, null, null, 103]:
Dec  4 15:49:27 orocrm console[19935]: SQLSTATE[22008]: Datetime field overflow: 7 ERROR:  date/time field value out of range: "0000-03-28 18:26:59"
Dec  4 15:49:27 orocrm console[19935]: LINE 1: ...ease check out the file.', 'firstname.lastname@iserv.eu', '0000-03-2...
Dec  4 15:49:27 orocrm console[19935]:                                                              ^ {"processor":"Oro\Bundle\ImapBundle\Async\SyncEmailMessageProcessor","topic":"oro.imap.sync_email","message":{"id":41}} {"exception":"[object] (Doctrine\DBAL\Exception\DriverException(code: 0): An exception occurred while executing 'INSERT INTO oro_email (serialized_data, created, subject, from_name, sent, importance, internaldate, is_head, message_id, multi_message_id, x_message_id, x_thread_id, refs, acceptLanguageHeader, body_synced, thread_id, email_body_id, from_email_address_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)' with params [\"Tjs=\", \"2017-12-04 14:49:27\", \"firstname.lastname Your Electricity Bill 3426$, Please check out the file.\", \"firstname.lastname@iserv.eu\", \"0000-03-28 18:26:59\", 1, \"2016-03-23 12:27:20\", 1, \"<000101d18531$96344e62$c0a80001@directwifi.com.br>\", null, \"\", \"\", null, \"\", null, null, null, 103]:
Dec  4 15:49:27 orocrm console[19935]: SQLSTATE[22008]: Datetime field overflow: 7 ERROR:  date/time field value out of range: \"0000-03-28 18:26:59\"
Dec  4 15:49:27 orocrm console[19935]: LINE 1: ...ease check out the file.', 'firstname.lastname@iserv.eu', '0000-03-2...
Dec  4 15:49:27 orocrm console[19935]:                                                              ^ at /var/www/crm-application/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractPostgreSQLDriver.php:91, Doctrine\DBAL\Driver\PDOException(code: 22008): SQLSTATE[22008]: Datetime field overflow: 7 ERROR:  date/time field value out of range: \"0000-03-28 18:26:59\"
Dec  4 15:49:27 orocrm console[19935]: LINE 1: ...ease check out the file.', 'firstname.lastname@iserv.eu', '0000-03-2...
Dec  4 15:49:27 orocrm console[19935]:                                                              ^ at /var/www/crm-application/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:93, PDOException(code: 22008): SQLSTATE[22008]: Datetime field overflow: 7 ERROR:  date/time field value out of range: \"0000-03-28 18:26:59\"
Dec  4 15:49:27 orocrm console[19935]: LINE 1: ...ease check out the file.', 'firstname.lastname@iserv.eu', '0000-03-2...
Dec  4 15:49:27 orocrm console[19935]:                                                              ^ at /var/www/crm-application/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:91)"}
Dec  4 15:49:27 orocrm console[19935]: ERROR: Consuming interrupted by exception. "The email synchronization failed for the following origins: 41." {"processor":"Oro\Bundle\ImapBundle\Async\SyncEmailMessageProcessor","topic":"oro.imap.sync_email","message":{"id":41}} {"exception":"[object] (Exception(code: 0): The email synchronization failed for the following origins: 41. at /var/www/crm-application/vendor/oro/platform/src/Oro/Bundle/EmailBundle/Sync/AbstractEmailSynchronizer.php:621)"}
Dec  4 15:49:27 orocrm console[19935]:>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Dec  4 15:49:27 orocrm console[19935]:   [Exception]
Dec  4 15:49:27 orocrm console[19935]:   The email synchronization failed for the following origins: 41.
Dec  4 15:49:27 orocrm console[19935]:>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Dec  4 15:49:27 orocrm console[19935]: oro:message-queue:consume [--message-limit MESSAGE-LIMIT] [--time-limit TIME-LIMIT] [--memory-limit MEMORY-LIMIT] [-h|--help] [-q|--quiet] [-v|vv|vvv|--verbose] [-V|--version] [--ansi] [--no-ansi] [-n|--no-interaction] [-s|--shell] [--process-isolation] [-e|--env ENV] [--no-debug] [--current-user CURRENT-USER] [--current-organization CURRENT-ORGANIZATION] [--disabled-listeners DISABLED-LISTENERS] [--] <command> [<clientDestinationName>]
Dec  4 15:49:27 orocrm systemd[1]: orocrm-consumer.service: Main process exited, code=exited, status=1/FAILURE
Dec  4 15:49:27 orocrm systemd[1]: orocrm-consumer.service: Unit entered failed state.
Dec  4 15:49:27 orocrm systemd[1]: orocrm-consumer.service: Failed with result 'exit-code'.
Dec  4 15:49:27 orocrm systemd[1]: orocrm-consumer.service: Service hold-off time over, scheduling restart.
Dec  4 15:49:27 orocrm systemd[1]: Stopped orocrm consume.

(I've replaced the name of my coworker with firstname.lastname.)

The headers of the mail that triggers this issue:

Return-Path: <firstname.lastname@directwifi.com.br>
Received: from iserv.iserv.eu (localhost [127.0.0.1])
         by iserv.iserv.eu (Cyrus v2.4.17-caldav-beta10-Debian-2.4.17+caldav~beta10-18) with LMTPA;
         Wed, 23 Mar 2016 13:27:20 +0100
X-Sieve: CMU Sieve 2.4
Received: from 186-249-219-17.directwifi.com.br ([186.249.219.17] helo=directwifi.com.br)
        by iserv.iserv.eu with smtp (Exim 4.84_2)
        (envelope-from <firstname.lastname@directwifi.com.br>)
        id 1aihsR-0004bM-8i
        for firstname.lastname@iserv.eu; Wed, 23 Mar 2016 13:27:20 +0100
Message-ID: <000101d18531$96344e62$c0a80001@directwifi.com.br>
From: firstname.lastname@iserv.eu
To: "firstname.lastname" <firstname.lastname@iserv.eu>
Reply-To: firstname.lastname@iserv.eu
Subject: firstname.lastname Your Electricity Bill 3426$, Please check out the file.
Importance: High
Date: Tue, 23 Mar 2016 18:26:59 0000
MIME-Version: 1.0
Content-Type: multipart/related;
        boundary="----=_NextPart_000_0001_01D18531.9634509C"
X-Priority: 3
X-MSMail-Priority: Normal
X-Mailer: Microsoft Outlook Express 6.00.2900.3138
X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.3138
X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on iserv.iserv.eu
X-Spam-Flag: YES
X-Spam-Level: ************
X-Spam-Status: Yes, score=12.4 required=5.0 autolearn=no autolearn_force=no
X-Spam-Report: 
 *  1.1 INVALID_DATE Invalid Date: header (not RFC 2822)
 *  0.0 TVD_RCVD_IP Message was received from an IP address
 *  3.0 DATE_IN_FUTURE_03_06 Date: is 3 to 6 hours after Received: date
 * -0.0 T_RP_MATCHES_RCVD Envelope sender domain matches handover relay
 *      domain
 *  0.0 HEADER_FROM_DIFFERENT_DOMAINS From and EnvelopeFrom 2nd level mail
 *      domains are different
 *  0.8 BAYES_50 BODY: Bayes spam probability is 40 to 60%
 *      [score: 0.5005]
 *  2.0 GENERIC_IXHASH BODY: iXhash found @ generic.ixhash.net
 *  1.0 RDNS_DYNAMIC Delivered to internal network by host with
 *      dynamic-looking rDNS
 *  2.0 MIME_NO_TEXT No (properly identified) text body parts
 *  2.5 DOS_OE_TO_MX Delivered direct to MX with OE headers

Unfortunately this problem seems to break the message consumer completely. It now fills up our syslog with error messages, and the database has been growing massively in size:

orocrm.iserv.eu ~ # ll /var/log/syslog{,-20171203}
-rw-r----- 1 root adm 65M Dez  4 16:07 /var/log/syslog
-rw-r----- 1 root adm 98M Dez  4 00:00 /var/log/syslog-20171203

orocrm.iserv.eu ~ # ll /var/backups/postgresql 
insgesamt 1,2G
-rw------- 1 root root 1,6M Nov  5 01:05 pgdump.2017-11-05.xz
-rw------- 1 root root 4,1M Nov 12 01:07 pgdump.2017-11-12.xz
-rw------- 1 root root 4,7M Nov 19 01:07 pgdump.2017-11-19.xz
-rw------- 1 root root 5,0M Nov 24 01:07 pgdump.2017-11-24.xz
-rw------- 1 root root 5,0M Nov 25 01:07 pgdump.2017-11-25.xz
-rw------- 1 root root 5,1M Nov 26 01:07 pgdump.2017-11-26.xz
-rw------- 1 root root 5,1M Nov 27 01:07 pgdump.2017-11-27.xz
-rw------- 1 root root 5,2M Nov 28 01:07 pgdump.2017-11-28.xz
-rw------- 1 root root 5,2M Nov 29 01:07 pgdump.2017-11-29.xz
-rw------- 1 root root  37M Nov 30 01:08 pgdump.2017-11-30.xz
-rw------- 1 root root  38M Dez  1 01:07 pgdump.2017-12-01.xz
-rw------- 1 root root 314M Dez  2 01:13 pgdump.2017-12-02.xz
-rw------- 1 root root 315M Dez  3 01:14 pgdump.2017-12-03.xz
-rw------- 1 root root 424M Dez  4 15:53 pgdump.2017-12-04.xz

Database backend is postgresql:

orocrm.iserv.eu /var/www/orocrm # head app/config/parameters.yml
# This file is auto-generated during the composer install
parameters:
    database_driver: pdo_pgsql
    database_host: localhost
    database_port: null
    database_name: oro_crm
    database_user: oro_crm
    database_password: ...
    mailer_transport: smtp
    mailer_host: 127.0.0.1
orocrm.iserv.eu ~ # dpkg -l | grep postgresql
ii  postgresql                       9.6+181+deb9u1                 all          object-relational SQL database (supported version)
ii  postgresql-9.6                   9.6.6-0+deb9u1                 amd64        object-relational SQL database, version 9.6 server
ii  postgresql-client-9.6            9.6.6-0+deb9u1                 amd64        front-end programs for PostgreSQL 9.6
ii  postgresql-client-common         181+deb9u1                     all          manager for multiple PostgreSQL client versions
ii  postgresql-common                181+deb9u1                     all          PostgreSQL database-cluster manager
manowark commented 6 years ago

Hello, @martinvonwittich.

It seems field sent parsed incorrect from string Tue, 23 Mar 2016 18:26:59 0000.

Thank you for reporting the issue! We greatly appreciate all contributions to Oro projects.

Could you please clarify version of our application?

I created internal task to fix this problem (Internal ID: BAP-16168).

martinvonwittich commented 6 years ago

Could you please clarify version of our application?

Is this the right way to determine the version?

orocrm.iserv.eu /var/www/orocrm # git branch                
* 2.5
anyt commented 6 years ago

You can check it at the management console at System > System Information menu.

manowark commented 5 years ago

Hi @martinvonwittich. Fixed in master by commit https://github.com/oroinc/platform/commit/c93842d44b82ca95997e87a86a7955b17a8e0e70.