Page MenuHomePhabricator
Create Task
Maniphest T12130

DateTime parsing error in phd log
Closed, InvalidPublic
Actions

Description

I'm seeing this error log in phd logs every a few seconds though I haven't found any impact yet:

[20-Jan-2017 10:22:54 Asia/Shanghai] [2017-01-20 10:22:54] EXCEPTION: (PhutilProxyException) Error while executing Task ID 1171793. {>} (Exception) DateTime::__construct(): Failed to parse time string (@) at position 0 (@): Unexpected character at [<phutil>/src/parser/calendar/data/PhutilCalendarAbsoluteDateTime.php:63]
[20-Jan-2017 10:22:54 Asia/Shanghai] arcanist(head=master, ref.master=e17fe43ca3fe), phabricator(head=cyyun, ref.master=cfcc3b834d1d, ref.cyyun=d09045a51b3a, custom=2), phutil(head=cyyun, ref.master=89984ac20059, ref.cyyun=5bc5bde08be9), sprint(head=master, ref.master=df6e9dee03e4)
[20-Jan-2017 10:22:54 Asia/Shanghai]   #0 <#2> DateTime::__construct(string) called at [<phutil>/src/parser/calendar/data/PhutilCalendarAbsoluteDateTime.php:63]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #1 <#2> PhutilCalendarAbsoluteDateTime::newFromEpoch(NULL) called at [<phabricator>/src/applications/calendar/storage/PhabricatorCalendarEvent.php:728]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #2 <#2> PhabricatorCalendarEvent::newIntermediateEventNode(PhabricatorUser, array) called at [<phabricator>/src/applications/calendar/util/PhabricatorCalendarICSWriter.php:50]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #3 <#2> PhabricatorCalendarICSWriter::writeICSDocument() called at [<phabricator>/src/applications/calendar/editor/PhabricatorCalendarEventEditor.php:360]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #4 <#2> PhabricatorCalendarEventEditor::newICSAttachment(PhabricatorCalendarEvent) called at [<phabricator>/src/applications/calendar/editor/PhabricatorCalendarEventEditor.php:333]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #5 <#2> PhabricatorCalendarEventEditor::buildMailBody(PhabricatorCalendarEvent, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:2517]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #6 <#2> PhabricatorApplicationTransactionEditor::buildMailForTarget(PhabricatorCalendarEvent, array, PhabricatorMailTarget) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:2474]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #7 <#2> PhabricatorApplicationTransactionEditor::buildMail(PhabricatorCalendarEvent, array) called at [<phabricator>/src/applications/transactions/editor/PhabricatorApplicationTransactionEditor.php:1156]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #8 <#2> PhabricatorApplicationTransactionEditor::publishTransactions(PhabricatorCalendarEvent, array) called at [<phabricator>/src/applications/transactions/worker/PhabricatorApplicationTransactionPublishWorker.php:21]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #9 <#2> PhabricatorApplicationTransactionPublishWorker::doWork() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorWorker.php:123]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #10 <#2> PhabricatorWorker::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php:171]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #11 <#2> PhabricatorWorkerActiveTask::executeTask() called at [<phabricator>/src/infrastructure/daemon/workers/PhabricatorTaskmasterDaemon.php:22]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #12 PhabricatorTaskmasterDaemon::run() called at [<phutil>/src/daemon/PhutilDaemon.php:181]
[20-Jan-2017 10:22:54 Asia/Shanghai]   #13 PhutilDaemon::execute() called at [<phutil>/scripts/daemon/exec/exec_daemon.php:127]

version info:

phabricator    d09045a51b3a12955640e4de27268bc7976328ad (Dec 1 2016) 
arcanist    e17fe43ca3fe6dc6dd0b5ce056f56310ea1d3d51 (Oct 22 2016) 
phutil    5bc5bde08be9d5da49c1728c104c161da69b3677 (Dec 1 2016) 
sprint    df6e9dee03e4dd0da551199df33b6d04bf096d32 (Apr 11 2016)

Related Objects

Event Timeline

RuralHunter created this task.Jan 20 2017, 2:31 AM
chad added a subscriber: chad.EditedJan 20 2017, 2:34 AM

You're at least 6 weeks out of date. Can you update Phabricator and verify the bug at HEAD before filing, please?

chad added a comment.Jan 20 2017, 2:39 AM

We will also need reproduction steps to accept this as a valid bug report. See Contributing Bug Reports.

chad edited projects, added Bug Report (Needs Information); removed Bug Report.Jan 20 2017, 2:40 AM
RuralHunter added a comment.Jan 20 2017, 2:47 AM

Actually this error started quite long ago. In my memory it started after some big changes on Calendar app. I have updated several versions before I fired this bug report. I will try to update to the latest version later. Regarding the reproduction steps, this is a background daemon log, not triggered by direct human action. I have no idea how to provide the reproduction steps. Any hint?

chad added a comment.Jan 20 2017, 3:00 AM

I'd update Phabricator first, then see if it clears.

chad added a comment.Jan 20 2017, 3:01 AM

Beyond that I don't know how you're using Calendar or what types of events you have.

epriestley mentioned this in T12134: Develop a Nuance-based Phabricator reporting/support flow.Jan 20 2017, 5:32 PM
RuralHunter added a comment.Jan 22 2017, 1:28 AM

I'm still seeing this in the latest code:
phabricator

c63ba8337ec7e7f021f17c972e9a2a751f6280e2 (Sat, Jan 21)

arcanist

9503b941cc02be637d967bb50cfb25f852e071e4 (Sat, Jan 7)

phutil

6d8f5a783ebe7993b78632091507f6d7d8cbc215 (Sat, Jan 21)
chad added a comment.Jan 22 2017, 1:30 AM

Thanks! Do you know how we can reproduce the error locally?

RuralHunter added a comment.Jan 22 2017, 1:34 AM

No idea, I guess this is something related to the Calendar events in my install as you mentioned. I'm wondering if there is some place in the code I can add some lines to log/debug the actual event and the date/time string which caused the error? I can edit the source and run it again.

chad added a comment.Jan 22 2017, 1:41 AM

We'd be happy to help you further under Phacility Consulting services. We unfortunately do not take bug reports without reproduction steps or against prototype applications (Calendar).

chad closed this task as Invalid.Jan 22 2017, 1:42 AM
chad added a comment.Jan 22 2017, 4:36 AM

If you do find a way to reproduce the bug, please reply back and we'll look into it.

RuralHunter added a comment.EditedJan 22 2017, 9:20 AM

I added some log in src/applications/calendar/storage/PhabricatorCalendarEvent.php before line 728 like this:

if ($this->isChildEvent()) {
      $parent = $this->getParentEvent();
      error_log("utc string:".$this->getUTCInstanceEpoch(),3,"/tmp/phadebug.log");
      $instance_datetime = PhutilCalendarAbsoluteDateTime::newFromEpoch(
        $this->getUTCInstanceEpoch());
      $recurrence_id = $instance_datetime->getISO8601();
      $rrule = null;
    }

It indicates $this->getUTCInstanceEpoch() returns empty or null. Any help for this? And I guess it should be related to some recurring events.

RuralHunter added a project: Calendar.Jan 23 2017, 7:11 AM

just FYI, I checked the database and found the utcInstanceEpoch is NULL for some old events, which maybe caused by bug in data migration during upgrade.

mysql> select id,datecreated,datemodified,isRecurring,utcInstanceEpoch from calendar_event;
 ---- ------------- -------------- ------------- ------------------ 
| id | datecreated | datemodified | isRecurring | utcInstanceEpoch |
 ---- ------------- -------------- ------------- ------------------ 
|  1 |  1402304273 |   1402304273 |           0 |             NULL |
|  2 |  1470721047 |   1470721712 |           0 |             NULL |
|  3 |  1471499490 |   1471501159 |           0 |             NULL |
|  4 |  1476760603 |   1478503571 |           1 |             NULL |
|  5 |  1476760809 |   1476760810 |           1 |             NULL |
|  6 |  1478504646 |   1478504647 |           1 |       1479693600 |
|  7 |  1478504677 |   1478504678 |           1 |       1478484000 |
|  8 |  1478504679 |   1478504680 |           1 |       1479088800 |
|  9 |  1485077510 |   1485077510 |           1 |       1482717600 |
| 10 |  1485139509 |   1485139510 |           1 |       1485136800 |
 ---- ------------- -------------- ------------- ------------------ 
10 rows in set (0.00 sec)
RuralHunter added a subscriber: epriestley.Jan 23 2017, 7:12 AM
RuralHunter added a comment.Jan 23 2017, 7:27 AM

I just created a simple test event and the utcInstanceEpoch column is still NULL. What does this column mean?

mysql> select id,name,datecreated,datemodified,isRecurring,utcInstanceEpoch from calendar_event where id=13;
 ---- ------ ------------- -------------- ------------- ------------------ 
| id | name | datecreated | datemodified | isRecurring | utcInstanceEpoch |
 ---- ------ ------------- -------------- ------------- ------------------ 
| 13 | test |  1485156335 |   1485156335 |           0 |             NULL |
 ---- ------ ------------- -------------- ------------- ------------------ 
1 row in set (0.00 sec)
RuralHunter added a comment.EditedJan 23 2017, 7:35 AM

OK, it seems utcInstanceEpoch is only used in child event of recurring events according to the code. After I canceled the recurring event(E4), there is no more error in phd log.

Phabricator · Built by Phacility