Canalplan Bug Tracker



Anonymous Login
2019-02-18 00:14 GMT

View Issue Details Jump to Notes ]
IDProjectCategoryView StatusLast Update
0000082Canalplan [All Projects] Bugpublic2016-03-12 17:20
ReporterShultzy 
Assigned ToNick Atty 
PriorityhighSeveritymajorReproducibilityalways
StatusclosedResolutionfixed 
PlatformMicrosoftOSWindowsOS Version8.1
Product VersionProduct Build 
Target VersionFixed in Version9.26.4 
Summary0000082: Queued items executed out of order [was: Marker places not saving]
DescriptionOnly the last marker place in a section is saved. See [Atlantic Intracoastal Waterway > Jacksonville to Savannah] the first four sections between bridges show only 3 new marker places added.a
TagsNo tags attached.
Attached Files

-Relationships
+Relationships

-Notes

~0000283

Nick Atty (administrator)

Got that - it's a bug in the new queueing code: all queued items generated from one change are written to the same file, leaving only the last.

~0000285

Shultzy (updater)

It appears that although the markers are in the correct position the order in which they are joined up by the route line is bizarre.

See [Atlantic Intracoastal Waterway > Savannah to Charleston > Savannah, Georgia]

As a test I entered them in this order from [Savannah, Georgia] to [Sam Varnedoe Bascule Bridge]
"!5ekc"
"!5ekd"
"!5ekb"
"!5eke"
"!5eka"

~0000286

Nick Atty (administrator)

This may take a while to fix. The problem is the resolution of time-stamps in the file system not being adequate. I'll try, but can't promise to fix it soon as I don't have a big chunk of programming time.

Sorry!

~0000287

Shultzy (updater)

Ok, I'll delete all the markers and wait till you have fixed it.

~0000288

user3

We should be able to get timestamps down to a very small value:

Stat at the command line produces things like:

stat 217.70.44.165@2457420.58051
  File: ‘217.70.44.165@2457420.58051
  Size: 9364 Blocks: 24 IO Block: 4096 regular file
Device: 832h/2098d Inode: 3019467 Links: 1
Access: (0644/-rw-r--r--) Uid: ( 33/www-data) Gid: ( 33/www-data)
Access: 2016-02-02 01:55:56.584803362 +0000
Modify: 2016-02-02 01:55:56.584803362 +0000
Change: 2016-02-02 01:55:56.584803362 +0000
 Birth: -

~0000289

Nick Atty (administrator)

Yes, that was an oversimplification. The values can be got out of stat(2) if you define the right constants to the build (the wrong ones - like the ANSI C ones - fail all sorts of unistd stuff).

But the sort routine needs to be rewritten to compare structures with two fields (a seconds and a nanoseconds field) and although I've got it sort of working it's not doing quite what it should in testing. And that's enough for the evening.

~0000290

Nick Atty (administrator)

I woke up early - give it a go now...

~0000292

Shultzy (updater)

Not quite, this is the order I created them from [Savannah, Georgia] to [Sam Varnedoe Bascule Bridge].
Marker place "!29q8"
Marker place "!5eka"
Marker place "!5ekc"
Marker place "!5ekb"
Marker place "!5ekd"

~0000293

Shultzy (updater)

Not a great issue but a consequence of deleting so many markers is shown in the [New Contributions] section

~0000295

Nick Atty (administrator)

Clearly a reproducable bug when you hack up the appropriate test harness. 10 ordered items were executed as: 3,5,2,1,4,7,9,6,10,8

Programming time is limited at the moment but I'm on it.

~0000296

Nick Atty (administrator)

And here's why we have a problem:

  File: ‘transaction_log/main_queue/07_19_15_9428_0_debug’
  Size: 13 Blocks: 8 IO Block: 4096 regular file
Device: 801h/2049d Inode: 27532163 Links: 1
Access: (0664/-rw-rw-r--) Uid: ( 1000/ nick) Gid: ( 1000/ nick)
Access: 2016-02-05 07:19:15.185413191 +0000
Modify: 2016-02-05 07:19:15.185413191 +0000
Change: 2016-02-05 07:19:15.185413191 +0000
 Birth: -
  File: ‘transaction_log/main_queue/07_19_15_9428_10_quit’
  Size: 11 Blocks: 8 IO Block: 4096 regular file
Device: 801h/2049d Inode: 27532192 Links: 1
Access: (0664/-rw-rw-r--) Uid: ( 1000/ nick) Gid: ( 1000/ nick)
Access: 2016-02-05 07:19:16.185413190 +0000
Modify: 2016-02-05 07:19:16.185413190 +0000
Change: 2016-02-05 07:19:16.185413190 +0000
 Birth: -
  File: ‘transaction_log/main_queue/07_19_15_9428_1_debug’
  Size: 13 Blocks: 8 IO Block: 4096 regular file
Device: 801h/2049d Inode: 27532172 Links: 1
Access: (0664/-rw-rw-r--) Uid: ( 1000/ nick) Gid: ( 1000/ nick)
Access: 2016-02-05 07:19:15.185413191 +0000
Modify: 2016-02-05 07:19:15.185413191 +0000
Change: 2016-02-05 07:19:15.185413191 +0000
 Birth: -
  File: ‘transaction_log/main_queue/07_19_15_9428_2_debug’
  Size: 13 Blocks: 8 IO Block: 4096 regular file
Device: 801h/2049d Inode: 27532174 Links: 1
Access: (0664/-rw-rw-r--) Uid: ( 1000/ nick) Gid: ( 1000/ nick)
Access: 2016-02-05 07:19:15.185413191 +0000
Modify: 2016-02-05 07:19:15.185413191 +0000
Change: 2016-02-05 07:19:15.185413191 +0000

I'm getting exactly the same inside my code which uses the library "stat". You can see there that the last file to be created actually has a slightly /earlier/ time. I've not seen that in previous tests, they've all been identical.

~0000297

Nick Atty (administrator)

I have now fixed the bug in testing, and will release on Sunday when I'm around to monitor any ill effects.

The underlying cause is that the ext4 file system caches the system clock at the frequency of the interrupt timer. The canalplan interpreter runs fast enough to have queued several updates in that time (yes, that surprised me too!). Since these files all have the same creation time they get executed in a random order.

See http://stackoverflow.com/questions/14392975/timestamp-accuracy-on-ext4-sub-millsecond for more discussion.

I've implemented a version of the technique suggested and whenever a file is closed I stamp it with the precise system time to the highest resolution available. In testing this does mean that queued items are always executed in the same order that they were created.

~0000299

Nick Atty (administrator)

Fixed by the magic power of futimens. Release pulled forward to today because boat work cancelled due to foul weather.

~0000301

Shultzy (updater)

Deleting two adjacent marker places produced those "database locked" error messages. This could also be related to the timing issues.

~0000302

Nick Atty (administrator)

No, that's just that deleting places requires a lot of work in the background and if you start to delete another place before it's finished it can get locked up.

This is why we queue multiple marker places, but deletions are normally so few-and-far-between that there's no problem.

~0000333

Autoclose (administrator)

Closing automatically, stayed too long in feedback state. Feel free to re-open with additional information if you think the issue is not resolved.
+Notes

-Issue History
Date Modified Username Field Change
2016-02-01 23:21 Shultzy New Issue
2016-02-02 07:11 Nick Atty Note Added: 0000283
2016-02-02 07:11 Nick Atty Status new => confirmed
2016-02-02 07:15 Nick Atty Resolution open => fixed
2016-02-02 07:15 Nick Atty Fixed in Version => 9.26.4
2016-02-02 12:38 Shultzy Note Added: 0000285
2016-02-02 18:35 Nick Atty Note Added: 0000286
2016-02-02 19:18 Shultzy Note Added: 0000287
2016-02-02 19:45 user3 Note Added: 0000288
2016-02-02 20:05 Nick Atty Note Added: 0000289
2016-02-03 07:32 Nick Atty Note Added: 0000290
2016-02-03 11:55 Shultzy Note Added: 0000292
2016-02-03 12:01 Shultzy Note Added: 0000293
2016-02-04 19:22 user3 Assigned To => Nick Atty
2016-02-04 19:22 user3 Status confirmed => assigned
2016-02-05 06:59 Nick Atty Note Added: 0000295
2016-02-05 06:59 Nick Atty Summary Marker places not saving => Queued items executed out of order [was: Marker places not saving]
2016-02-05 06:59 Nick Atty Description Updated View Revisions
2016-02-05 07:21 Nick Atty Note Added: 0000296
2016-02-06 06:45 Nick Atty Note Added: 0000297
2016-02-06 11:09 Nick Atty Note Added: 0000299
2016-02-06 11:09 Nick Atty Status assigned => resolved
2016-02-06 16:49 Shultzy Note Added: 0000301
2016-02-06 16:49 Shultzy Status resolved => feedback
2016-02-06 16:49 Shultzy Resolution fixed => reopened
2016-02-07 07:41 Nick Atty Note Added: 0000302
2016-02-07 07:41 Nick Atty Status feedback => resolved
2016-02-07 07:41 Nick Atty Resolution reopened => fixed
2016-03-12 17:20 Autoclose Note Added: 0000333
2016-03-12 17:20 Autoclose Status resolved => closed
+Issue History