Modify ↓

Opened 11 years ago

Closed 10 years ago

#11773 closed defect (fixed)

schedule and schedule_change tables not written to

Reported by: jc Owned by: Chris Nelson
Priority: high Component: TracJsGanttPlugin
Severity: critical Keywords:
Cc: Trac Release: 1.0

Description

(background to this ticket: https://trac-hacks.org/ticket/11761)

tracpm.py: rescheduleTickets: contains line like: 

   2913                             values.append(to_utimestamp(self.pm.finish(t)))
   2914                     cursor.execute('INSERT INTO schedule' + \
   2915                                        ' (ticket, start, finish)' + \
   2916                                        ' VALUES %s' % valuesClause,
   2917                                    values)

These inserts are queued but rolled back instead of being commited.

The following patch ensures the inserts are carried out, but may have side effects: def rescheduleTickets(self, ticket, old_values) (at the very bottom): 

        profile.append([ 'inserting', len(toInsert), end - start ])

+       db.commit()
        for step in profile:
            self.env.log.info('TracPM:%s %s tickets took %s' %
                              (step[0], step[1], step[2]))

This following guidance in ​http://trac.edgewall.org/wiki/TracDev/DatabaseApi, a db.commit() has to be explicitly added with cnx connections. They also state: The use of env.get_db_cnx() is now strongly discouraged. etc.

Side-effects: In fact, by forcing a commit, existing diagrams are drawn in completely new ways, with tasks previously "anchored" say in April, now appearing at the end of July.

This effect is documented in https://trac-hacks.org/attachment/ticket/11761/CommitEnabled1.pdf

This may be a reason why these tables were not written to(?)

Attachments (0)

Change History (19)

comment:1 Changed 10 years ago by jc

As suggested in: https://trac-hacks.org/ticket/11761#comment:22 I tried the TracJSGanttChart "command" with/without milestone: 

Error: Macro TracJSGanttChart(scheduled=1,schedule=none,milestone=dummymilestone) failed

'NoneType' object has no attribute 'strftime'

Error: Macro TracJSGanttChart(scheduled=1,schedule=none) failed

can't compare datetime.datetime to NoneType

comment:2 in reply to:  1 Changed 10 years ago by Chris Nelson

Replying to jamescook:

As suggested in: https://trac-hacks.org/ticket/11761#comment:22 I tried the TracJSGanttChart "command" with/without milestone: 

Error: Macro TracJSGanttChart(scheduled=1,schedule=none,milestone=dummymilestone) failed

'NoneType' object has no attribute 'strftime'

Error: Macro TracJSGanttChart(scheduled=1,schedule=none) failed

can't compare datetime.datetime to NoneType

That may be because the table is empty and it's trying to post-process 0 tasks from the database.

Try setting 

[TracPM]
logScheduling=1

in trac.ini then look for lines including "sch>" in trac.log. Though I'm also interested in anything about database rollbacks.

As noted, we're in 0.11.6 and PostgreSQL 9.1.13. You're in 1.0.1, right?

comment:3 Changed 10 years ago by anonymous

Just to say I'm looking into this again now

comment:4 Changed 10 years ago by jc

Trac Version is: 1.0.1 postgres is: 9.1.12

Below more details if you need them:

System: 

Trac 	1.0.1
Babel 	0.9.6
Docutils 	0.8.1
Genshi 	0.6 (with speedups)
mod_wsgi 	3.3 (WSGIProcessGroup WSGIApplicationGroup %{GLOBAL})
psycopg2 	2.5.3
Pygments 	1.4
Python 	2.7.3 (default, Feb 27 2014, 20:09:21) [GCC 4.6.3]
pytz 	2011k
RPC 	1.1.2-r13776
setuptools 	3.2
Subversion 	1.6.17 (r1128011)
jQuery	1.7.2

Plugins: 

timingandestimationplugin 	1.3.7b 	/usr/local/lib/python2.7/dist-packages/timingandestimationplugin-1.3.7b-py2.7.egg
Trac-jsGantt 	0.10-r13868 	/usr/local/lib/python2.7/dist-packages/Trac_jsGantt-0.10_r13868-py2.7.egg
TracDateField 	3.0.0dev-r12118 	/usr/local/lib/python2.7/dist-packages/TracDateField-3.0.0dev_r12118-py2.7.egg
TracDragDrop 	0.12.0.12-r13613 	/usr/local/lib/python2.7/dist-packages/TracDragDrop-0.12.0.12_r13613-py2.7.egg
TracGanttCalendarPlugin 	0.6.2 	/usr/local/lib/python2.7/dist-packages/TracGanttCalendarPlugin-0.6.2-py2.7.egg
TracMasterTickets 	3.0.5dev-r13684 	/usr/local/lib/python2.7/dist-packages/TracMasterTickets-3.0.5dev_r13684-py2.7.egg
TracMigratePlugin 	0.12.0.3 	/usr/local/lib/python2.7/dist-packages/TracMigratePlugin-0.12.0.3-py2.7.egg
TracSubTicketsPlugin 	0.2.0.dev-20140315 	/usr/local/lib/python2.7/dist-packages/TracSubTicketsPlugin-0.2.0.dev_20140315-py2.7.egg
TracXMLRPC 	1.1.2-r13776 	/usr/local/lib/python2.7/dist-packages/TracXMLRPC-1.1.2_r13776-py2.7.egg

comment:5 Changed 10 years ago by jc

Schedule tables are both empty: 

tracdb=# select * from schedule_change;
 ticket | time | oldstart | oldfinish | newstart | newfinish
--------+------+----------+-----------+----------+-----------
(0 rows)

tracdb=# select * from schedule;
 ticket | start | finish
--------+-------+--------
(0 rows)

comment:6 Changed 10 years ago by jc

Ok, I'm now checking to see that I'm using the original (non-modified) version of tracpm.py - i.e. the one without the added commit line. 

diff tracpm.py tracpm.py.ORIG
2889d2888
<             #db.commit();

Well, the line is commented out.

The full location is: /usr/local/lib/python2.7/dist-packages/Trac_jsGantt-0.10_r13868-py2.7.egg

comment:7 Changed 10 years ago by jc

Hopefully that's the setup set correctly: Now I change the start date of 502 from 1.4.2014 to 8.1.2014:

  • jsgantt diagram is adjusted correctly

Here are the "sch>" entries from the log concerning this change at about 11:23, 11.24: 

2014-06-25 11:23:18,052 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.052554 and 2014-06-25 12:23:18.052554 gives 1
2014-06-25 11:23:18,052 Trac[tracpm] INFO: sch>Scheduling 502
2014-06-25 11:23:18,211 Trac[tracpm] INFO: sch>Using explicit start: 2014-04-01 00:00:00+02:00
2014-06-25 11:23:18,211 Trac[tracpm] INFO: sch>502 scheduled start is [datetime.datetime(2014, 4, 1, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 3]
2014-06-25 11:23:18,211 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-04-01 07:00:00+02:00
2014-06-25 11:23:18,211 Trac[tracpm] INFO: sch>mike's limit was None
2014-06-25 11:23:18,211 Trac[tracpm] INFO: sch>Updating mike's limit to 2014-04-01 07:00:00+02:00
2014-06-25 11:23:18,212 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.212225 and 2014-06-25 12:23:18.212225 gives 1
2014-06-25 11:23:18,212 Trac[tracpm] INFO: sch>Scheduling 279
2014-06-25 11:23:18,212 Trac[tracpm] INFO: sch>Defaulting start: 2014-06-25 00:00:00+02:00
2014-06-25 11:23:18,212 Trac[tracpm] INFO: sch>279 scheduled start is [datetime.datetime(2014, 6, 25, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 6]
2014-06-25 11:23:18,212 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-27 04:00:00+02:00
2014-06-25 11:23:18,213 Trac[tracpm] INFO: sch>mike's limit was 2014-04-01 07:00:00+02:00
2014-06-25 11:23:18,213 Trac[tracpm] INFO: sch>comparing 2014-04-01 07:00:00+02:00 and 2014-06-27 04:00:00+02:00 gives 1
2014-06-25 11:23:18,213 Trac[tracpm] INFO: sch>Updating mike's limit to 2014-06-27 04:00:00+02:00
2014-06-25 11:23:18,213 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.213773 and 2014-06-25 12:23:18.213773 gives 1
2014-06-25 11:23:18,213 Trac[tracpm] INFO: sch>Scheduling 283
2014-06-25 11:23:18,214 Trac[tracpm] INFO: sch>Defaulting start: 2014-06-25 00:00:00+02:00
2014-06-25 11:23:18,214 Trac[tracpm] INFO: sch>283 scheduled start is [datetime.datetime(2014, 6, 25, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 6]
2014-06-25 11:23:18,214 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-25 04:00:00+02:00
2014-06-25 11:23:18,214 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.214828 and 2014-06-25 12:23:18.214828 gives 1
2014-06-25 11:23:18,214 Trac[tracpm] INFO: sch>Scheduling 503
2014-06-25 11:23:18,215 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.215064 and 2014-06-25 12:23:18.215064 gives 1
2014-06-25 11:23:18,215 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:23:18,215 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-01 07:00:00+02:00 gives -1
2014-06-25 11:23:18,215 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-04-01 07:00:00+02:00
2014-06-25 11:23:18,215 Trac[tracpm] INFO: sch>503 scheduled start is [datetime.datetime(2014, 4, 1, 7, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:23:18,215 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-04-02 03:00:00+02:00
2014-06-25 11:23:18,216 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:23:18,216 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-02 03:00:00+02:00 gives -1
2014-06-25 11:23:18,216 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.216567 and 2014-06-25 12:23:18.216567 gives 1
2014-06-25 11:23:18,216 Trac[tracpm] INFO: sch>Scheduling 504
2014-06-25 11:23:18,216 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.216816 and 2014-06-25 12:23:18.216816 gives 1
2014-06-25 11:23:18,217 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:23:18,217 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-02 03:00:00+02:00 gives -1
2014-06-25 11:23:18,217 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-04-02 03:00:00+02:00
2014-06-25 11:23:18,217 Trac[tracpm] INFO: sch>504 scheduled start is [datetime.datetime(2014, 4, 2, 3, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:23:18,217 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-04-02 07:00:00+02:00
2014-06-25 11:23:18,217 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:23:18,217 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-02 07:00:00+02:00 gives -1
2014-06-25 11:23:18,218 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.218327 and 2014-06-25 12:23:18.218327 gives 1
2014-06-25 11:23:18,218 Trac[tracpm] INFO: sch>Scheduling 280
2014-06-25 11:23:18,218 Trac[tracpm] INFO: sch>Using explicit start: 2014-03-01 00:00:00+01:00
2014-06-25 11:23:18,218 Trac[tracpm] INFO: sch>280 scheduled start is [datetime.datetime(2014, 3, 1, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 3]
2014-06-25 11:23:18,218 Trac[tracpm] INFO: sch>Using explicit finish: 2014-03-11 00:00:00+01:00
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.219081 and 2014-06-25 12:23:18.219081 gives 1
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>Scheduling 277
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>Using explicit start: 2014-05-23 00:00:00+02:00
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>277 scheduled start is [datetime.datetime(2014, 5, 23, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 3]
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-05-23 04:00:00+02:00
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.219521 and 2014-06-25 12:23:18.219521 gives 1
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>Scheduling 278
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.219622 and 2014-06-25 12:23:18.219622 gives 1
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-05-23 04:00:00+02:00
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>278 scheduled start is [datetime.datetime(2014, 5, 23, 4, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:23:18,219 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-03 02:00:00+02:00
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.220052 and 2014-06-25 12:23:18.220052 gives 1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>Scheduling 429
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.220150 and 2014-06-25 12:23:18.220150 gives 1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.220217 and 2014-06-25 12:23:18.220217 gives 1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-05-23 04:00:00+02:00
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>429 scheduled start is [datetime.datetime(2014, 5, 23, 4, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-05-23 08:00:00+02:00
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>'s limit was None
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>Updating 's limit to 2014-05-23 08:00:00+02:00
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.220701 and 2014-06-25 12:23:18.220701 gives 1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>Scheduling -1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.220801 and 2014-06-25 12:23:18.220801 gives 1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.220860 and 2014-06-25 12:23:18.220860 gives 1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.220918 and 2014-06-25 12:23:18.220918 gives 1
2014-06-25 11:23:18,220 Trac[tracpm] INFO: sch>'s limit was 2014-05-23 08:00:00+02:00
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>comparing 2014-05-23 08:00:00+02:00 and 2014-05-23 08:00:00+02:00 gives 0
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.221123 and 2014-06-25 12:23:18.221123 gives 1
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-02 07:00:00+02:00 gives -1
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:23:18.221312 and 2014-06-25 12:23:18.221312 gives 1
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-06-25 04:00:00+02:00
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>-1 scheduled start is [datetime.datetime(2014, 6, 25, 4, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:23:18,221 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-25 04:00:00+02:00
2014-06-25 11:25:31,557 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.557526 and 2014-06-25 12:25:31.557526 gives 1
2014-06-25 11:25:31,557 Trac[tracpm] INFO: sch>Scheduling 502
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>Using explicit start: 2014-04-08 00:00:00+02:00
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>502 scheduled start is [datetime.datetime(2014, 4, 8, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 3]
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-04-08 07:00:00+02:00
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>mike's limit was None
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>Updating mike's limit to 2014-04-08 07:00:00+02:00
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.559671 and 2014-06-25 12:25:31.559671 gives 1
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>Scheduling 279
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>Defaulting start: 2014-06-25 00:00:00+02:00
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>279 scheduled start is [datetime.datetime(2014, 6, 25, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 6]
2014-06-25 11:25:31,559 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-27 04:00:00+02:00
2014-06-25 11:25:31,560 Trac[tracpm] INFO: sch>mike's limit was 2014-04-08 07:00:00+02:00
2014-06-25 11:25:31,560 Trac[tracpm] INFO: sch>comparing 2014-04-08 07:00:00+02:00 and 2014-06-27 04:00:00+02:00 gives 1
2014-06-25 11:25:31,560 Trac[tracpm] INFO: sch>Updating mike's limit to 2014-06-27 04:00:00+02:00
2014-06-25 11:25:31,560 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.560597 and 2014-06-25 12:25:31.560597 gives 1
2014-06-25 11:25:31,560 Trac[tracpm] INFO: sch>Scheduling 283
2014-06-25 11:25:31,560 Trac[tracpm] INFO: sch>Defaulting start: 2014-06-25 00:00:00+02:00
2014-06-25 11:25:31,561 Trac[tracpm] INFO: sch>283 scheduled start is [datetime.datetime(2014, 6, 25, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 6]
2014-06-25 11:25:31,561 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-25 04:00:00+02:00
2014-06-25 11:25:31,561 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.561691 and 2014-06-25 12:25:31.561691 gives 1
2014-06-25 11:25:31,561 Trac[tracpm] INFO: sch>Scheduling 503
2014-06-25 11:25:31,561 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.561931 and 2014-06-25 12:25:31.561931 gives 1
2014-06-25 11:25:31,562 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:25:31,562 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-08 07:00:00+02:00 gives -1
2014-06-25 11:25:31,562 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-04-08 07:00:00+02:00
2014-06-25 11:25:31,562 Trac[tracpm] INFO: sch>503 scheduled start is [datetime.datetime(2014, 4, 8, 7, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:25:31,562 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-04-09 03:00:00+02:00
2014-06-25 11:25:31,562 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:25:31,563 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-09 03:00:00+02:00 gives -1
2014-06-25 11:25:31,563 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.563482 and 2014-06-25 12:25:31.563482 gives 1
2014-06-25 11:25:31,563 Trac[tracpm] INFO: sch>Scheduling 504
2014-06-25 11:25:31,563 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.563716 and 2014-06-25 12:25:31.563716 gives 1
2014-06-25 11:25:31,563 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:25:31,564 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-09 03:00:00+02:00 gives -1
2014-06-25 11:25:31,564 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-04-09 03:00:00+02:00
2014-06-25 11:25:31,564 Trac[tracpm] INFO: sch>504 scheduled start is [datetime.datetime(2014, 4, 9, 3, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:25:31,564 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-04-09 07:00:00+02:00
2014-06-25 11:25:31,564 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:25:31,564 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-09 07:00:00+02:00 gives -1
2014-06-25 11:25:31,565 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.565263 and 2014-06-25 12:25:31.565263 gives 1
2014-06-25 11:25:31,565 Trac[tracpm] INFO: sch>Scheduling 280
2014-06-25 11:25:31,565 Trac[tracpm] INFO: sch>Using explicit start: 2014-03-01 00:00:00+01:00
2014-06-25 11:25:31,565 Trac[tracpm] INFO: sch>280 scheduled start is [datetime.datetime(2014, 3, 1, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 3]
2014-06-25 11:25:31,565 Trac[tracpm] INFO: sch>Using explicit finish: 2014-03-11 00:00:00+01:00
2014-06-25 11:25:31,566 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.566300 and 2014-06-25 12:25:31.566300 gives 1
2014-06-25 11:25:31,566 Trac[tracpm] INFO: sch>Scheduling 277
2014-06-25 11:25:31,566 Trac[tracpm] INFO: sch>Using explicit start: 2014-05-23 00:00:00+02:00
2014-06-25 11:25:31,566 Trac[tracpm] INFO: sch>277 scheduled start is [datetime.datetime(2014, 5, 23, 0, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 3]
2014-06-25 11:25:31,566 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-05-23 04:00:00+02:00
2014-06-25 11:25:31,567 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.567329 and 2014-06-25 12:25:31.567329 gives 1
2014-06-25 11:25:31,567 Trac[tracpm] INFO: sch>Scheduling 278
2014-06-25 11:25:31,567 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.567588 and 2014-06-25 12:25:31.567588 gives 1
2014-06-25 11:25:31,567 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-05-23 04:00:00+02:00
2014-06-25 11:25:31,567 Trac[tracpm] INFO: sch>278 scheduled start is [datetime.datetime(2014, 5, 23, 4, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-03 02:00:00+02:00
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.568546 and 2014-06-25 12:25:31.568546 gives 1
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>Scheduling 429
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.568644 and 2014-06-25 12:25:31.568644 gives 1
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.568708 and 2014-06-25 12:25:31.568708 gives 1
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-05-23 04:00:00+02:00
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>429 scheduled start is [datetime.datetime(2014, 5, 23, 4, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-05-23 08:00:00+02:00
2014-06-25 11:25:31,568 Trac[tracpm] INFO: sch>'s limit was None
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>Updating 's limit to 2014-05-23 08:00:00+02:00
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.569211 and 2014-06-25 12:25:31.569211 gives 1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>Scheduling -1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.569312 and 2014-06-25 12:25:31.569312 gives 1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.569371 and 2014-06-25 12:25:31.569371 gives 1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.569428 and 2014-06-25 12:25:31.569428 gives 1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>'s limit was 2014-05-23 08:00:00+02:00
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-05-23 08:00:00+02:00 and 2014-05-23 08:00:00+02:00 gives 0
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.569613 and 2014-06-25 12:25:31.569613 gives 1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>mike's limit was 2014-06-27 04:00:00+02:00
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-06-27 04:00:00+02:00 and 2014-04-09 07:00:00+02:00 gives -1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>comparing 2014-06-25 11:25:31.569798 and 2014-06-25 12:25:31.569798 gives 1
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>Got start from dependencies: 2014-06-25 04:00:00+02:00
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>-1 scheduled start is [datetime.datetime(2014, 6, 25, 4, 0, tzinfo=<LocalTimezone "CET" 1:00:00 "CEST" 2:00:00>), 4]
2014-06-25 11:25:31,569 Trac[tracpm] INFO: sch>Computed finish from start, work: 2014-06-25 04:00:00+02:00

comment:8 Changed 10 years ago by jc

Well, there are no rollbacks AFAICT in the trac.log. On the other hand there are no rollbacks in the postgres log either. 

  22564 2014-06-25 11:24:19 CEST LOG:  statement: UPDATE ticket_custom SET value='2014-04-08'
  22565                                       WHERE ticket=502 AND name='userstart'
  22566
  22567 2014-06-25 11:24:19 CEST LOG:  statement: INSERT INTO ticket_change
  22568                                 (ticket,time,author,field,oldvalue,newvalue)
  22569                               VALUES (502, 1403688259144844, 'mike', 'userstart', '2014-04-01', '2014-04-08')
  22570
  22571 2014-06-25 11:24:19 CEST LOG:  statement: INSERT INTO ticket_change
  22572                             (ticket,time,author,field,oldvalue,newvalue)
  22573                           VALUES (502,1403688259144844,'mike','comment','53','')
  22574
  22575 2014-06-25 11:24:19 CEST LOG:  statement: COMMIT

But it's worth noting that these aren't changes to schedule or schedule_change tables

As a next step I'll try to find what would/should trigger a schedule change entry

comment:9 Changed 10 years ago by jc

Well, I'm a bit stuck. I can't generate any changes to the schedule in _updateScheduleDB -> tickets and idle are always empty so nothing is done.

I tried changing the Start Date of 502 - _updateScheduleDB is entered, but tickets and idle are 0 (len). 502 is reported as "is not active" and "was not active" (?). Adding hours, or changing estimated hours has the same effect.

Changing 504 by e.g. adding 20hrs doesn't even get to call _updateScheduleDB.

I changed the milestone (dummymilestone) due date from empty to today. Had no effect (I thought this might help 502 become active)

Taking a break now ...

comment:10 Changed 10 years ago by jc

It's very strange, I'm "sure" changing Start Date of 502 triggered rescheduling in the past (see e.g. https://trac-hacks.org/ticket/11761#comment:10).

Just to be sure I checked: 

tracjsgantt.tracpm.ticketrescheduler = enabled

it is set this way in trac.ini

Hmmm ... Something about the milestone and these tasks is now different ... (working on this)

Last edited 10 years ago by jc (previous) (diff)

comment:11 Changed 10 years ago by jc

My current "suspicion" is that it may be a r13705 v r13868 issue.

When initially reported and tested (with the report of the postgres rollback etc.) in https://trac-hacks.org/ticket/11761?cnum_edit=18#comment:10 I was using r13705. r13868 was installed "at" https://trac-hacks.org/ticket/11761?cnum_edit=18#comment:16.

Perhaps r13686 does no rescheduling were r13705 would have done (?) The code HAS changed in this area in particular rescheduleTickets's call to _updateScheduleDB is new etc.

(I "should" get some virtual envs going to make switching/testing less error prone.)

Last edited 10 years ago by jc (previous) (diff)

comment:12 in reply to:  11 Changed 10 years ago by Chris Nelson

Replying to jamescook:

My current "suspicion" is that it may be a r13705 v r13868 issue. ...

Only 1600 lines changed in 29 commits! Easy, peasy. :-/

I'd use git-bisect to find the issue but I don't know how you are managing the code.

Looking at the description of the commits, it might be interesting to try r13836 or r13837 which are sort of between two refactoring sprints.

comment:13 Changed 10 years ago by anonymous

Well my brand new laptop (sony) died on Thurday so I'm a bit limited rigging up an old laptop to continue.

As far as you know should changing the start date of 502 normally lead to a rescheduling (i.e. new entries in schedule and schedule_change)? - I'm fairly sure it did this in r13705.

The reason nothing is written is that despite the change 502 is deemed NOT to be WAS_ACTIVE and NOT to be IS_ACTIVE. Do you have any idea why this is the case? (What does IS_ACTIVE, WAS_ACTIVE mean - how is it established).

comment:14 Changed 10 years ago by jc

That last comment is from me - forgot to login ...

comment:15 Changed 10 years ago by jc

This from the log file shows what I mean about IS/WAS_ACTIVE: (r13837) 

2014-06-25 13:10:37,676 Trac[tracpm] INFO: Changes to 502 affect schedule.  Rescheduling.
2014-06-25 13:10:37,677 Trac[tracpm] DEBUG: 502 was not active
2014-06-25 13:10:37,677 Trac[tracpm] DEBUG: 502 is not active
2014-06-25 13:10:37,677 Trac[tracpm] INFO: Enter _updateScheduleDB
2014-06-25 13:10:37,678 Trac[tracpm] INFO: getting active goals 0 tickets took 0:00:00.000530
2014-06-25 13:10:37,678 Trac[tracpm] INFO: getting active tickets 0 tickets took 0:00:00.000013
2014-06-25 13:10:37,678 Trac[tracpm] INFO: getting scheduled tickets 0 tickets took 0:00:00.000428

comment:16 Changed 10 years ago by Chris Nelson

We're now in 1.0.1 and I see the same behavior. Hopefully, this will be fixed today.

comment:17 Changed 10 years ago by Chris Nelson

Yes, fixed locally. Testing.

comment:18 Changed 10 years ago by Chris Nelson

In 14075:

Save schedule under Trac 1.0, bump version. Refs #11773.

NOTE: This is incompatible with versions of Trac prior to 1.0!

Plugin version now 0.11. That's a little confusing since plugin 0.10
worked in Trac 0.11(.6). Sorry. This is temporary. Hopefully I'll get
some other changes in soon and bump the plugin version again.

There are other database accesses that should be converted to 1.0 style
but I haven't fully tested those changes yet.

comment:19 Changed 10 years ago by Chris Nelson

Resolution: → fixed
Status: new → closed

Not further activity. I'll assume this is fixed. (It works for us locally after our 1.0 upgrade.)

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Chris Nelson.
The resolution will be deleted. Next status will be 'reopened'.

Add Comment

E-mail address and name can be saved in the Preferences.

Attachments ↑ Description ↑
 
Note: See TracTickets for help on using tickets.