You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2013/03/18 18:48:17 UTC
[jira] [Created] (MESOS-403) CoordinatorTest.TruncateLearnedFill
test is flaky
Vinod Kone created MESOS-403:
--------------------------------
Summary: CoordinatorTest.TruncateLearnedFill test is flaky
Key: MESOS-403
URL: https://issues.apache.org/jira/browse/MESOS-403
Project: Mesos
Issue Type: Bug
Reporter: Vinod Kone
Assignee: Benjamin Hindman
[ RUN ] CoordinatorTest.TruncateLearnedFill
I0318 17:39:20.028264 2065 replica.cpp:229] Opened db in 227.23ms
I0318 17:39:20.096964 2065 replica.cpp:236] Compacted db in 68.64ms
I0318 17:39:20.097054 2065 replica.cpp:252] Created db iterator in 6.13us
I0318 17:39:20.097496 2065 replica.cpp:258] Seeked to beginning of db in 1.22us
I0318 17:39:20.097874 2065 replica.cpp:309] Iterated through 0 keys in the db in 858.00ns
I0318 17:39:20.098372 2065 replica.cpp:1039] Replica recovered with log positions 0 -> 0 and holes { 0 } and unlearned { }
I0318 17:39:20.307363 2065 replica.cpp:229] Opened db in 208.45ms
I0318 17:39:20.357430 2065 replica.cpp:236] Compacted db in 50.00ms
I0318 17:39:20.357481 2065 replica.cpp:252] Created db iterator in 4.31us
I0318 17:39:20.357892 2065 replica.cpp:258] Seeked to beginning of db in 1.19us
I0318 17:39:20.358299 2065 replica.cpp:309] Iterated through 0 keys in the db in 651.00ns
I0318 17:39:20.403089 2065 replica.cpp:1039] Replica recovered with log positions 0 -> 0 and holes { 0 } and unlearned { }
I0318 17:39:20.432387 2065 coordinator.cpp:60] Coordinator attempting to get elected within 2.00secs
I0318 17:39:20.433293 2214 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:20.433473 2210 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:20.499164 2214 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 65.82ms
I0318 17:39:20.499213 2214 replica.cpp:952] Persisted promise to 1
I0318 17:39:20.532687 2210 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 46.42ms
I0318 17:39:20.532732 2210 replica.cpp:952] Persisted promise to 1
I0318 17:39:20.533433 2065 coordinator.cpp:114] Coordinator elected, attempting to fill missing positions
I0318 17:39:20.533707 2065 coordinator.cpp:395] Coordinator attempting to fill position 0 in the log
I0318 17:39:20.535804 2217 replica.cpp:704] Replica received explicit promise request for 1 for position 0
I0318 17:39:20.535907 2214 replica.cpp:704] Replica received explicit promise request for 1 for position 0
I0318 17:39:20.626976 2217 replica.cpp:384] Persisting action (8 bytes) to leveldb took 44.82ms
I0318 17:39:20.663772 2217 replica.cpp:967] Persisted action at 0
I0318 17:39:20.648195 2214 replica.cpp:384] Persisting action (8 bytes) to leveldb took 65.10ms
I0318 17:39:20.665281 2214 replica.cpp:967] Persisted action at 0
I0318 17:39:20.690657 2065 coordinator.cpp:225] Coordinator attempting to write NOP action at position 0 within 1.74secs
I0318 17:39:20.691447 2212 replica.cpp:807] Replica received write request for position 0
I0318 17:39:20.691551 2212 replica.cpp:469] Reading position from leveldb took 32.62us
I0318 17:39:20.735716 2212 replica.cpp:384] Persisting action (14 bytes) to leveldb took 43.83ms
I0318 17:39:20.735756 2212 replica.cpp:967] Persisted action at 0
I0318 17:39:20.736775 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 0
I0318 17:39:20.765748 2212 replica.cpp:807] Replica received write request for position 0
I0318 17:39:20.766302 2212 replica.cpp:469] Reading position from leveldb took 15.74us
I0318 17:39:20.839989 2212 replica.cpp:384] Persisting action (16 bytes) to leveldb took 50.40ms
I0318 17:39:20.840040 2212 replica.cpp:967] Persisted action at 0
I0318 17:39:20.841089 2065 coordinator.cpp:384] Telling other replicas of learned action at position 0
I0318 17:39:20.864938 2217 replica.cpp:907] Replica received learned notice for position 0
I0318 17:39:20.864986 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 1 within 2.00secs
I0318 17:39:20.918839 2217 replica.cpp:384] Persisting action (16 bytes) to leveldb took 28.02ms
I0318 17:39:20.918952 2217 replica.cpp:967] Persisted action at 0
I0318 17:39:20.919309 2217 replica.cpp:912] Replica learned NOP action at position 0
I0318 17:39:20.919766 2217 replica.cpp:807] Replica received write request for position 1
I0318 17:39:20.948204 2217 replica.cpp:384] Persisting action (17 bytes) to leveldb took 27.97ms
I0318 17:39:20.948250 2217 replica.cpp:967] Persisted action at 1
I0318 17:39:20.948914 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 1
I0318 17:39:20.957237 2214 replica.cpp:807] Replica received write request for position 1
I0318 17:39:20.992838 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 35.37ms
I0318 17:39:20.992919 2214 replica.cpp:967] Persisted action at 1
I0318 17:39:20.994412 2065 coordinator.cpp:384] Telling other replicas of learned action at position 1
I0318 17:39:21.048689 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 2 within 2.00secs
I0318 17:39:21.048723 2214 replica.cpp:907] Replica received learned notice for position 1
I0318 17:39:21.091691 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 42.11ms
I0318 17:39:21.091739 2214 replica.cpp:967] Persisted action at 1
I0318 17:39:21.123368 2214 replica.cpp:912] Replica learned APPEND action at position 1
I0318 17:39:21.131989 2214 replica.cpp:807] Replica received write request for position 2
I0318 17:39:21.198143 2214 replica.cpp:384] Persisting action (17 bytes) to leveldb took 64.76ms
I0318 17:39:21.198252 2214 replica.cpp:967] Persisted action at 2
I0318 17:39:21.199764 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 2
I0318 17:39:21.241514 2217 replica.cpp:807] Replica received write request for position 2
I0318 17:39:21.356377 2217 replica.cpp:384] Persisting action (19 bytes) to leveldb took 91.73ms
I0318 17:39:21.356427 2217 replica.cpp:967] Persisted action at 2
I0318 17:39:21.356994 2065 coordinator.cpp:384] Telling other replicas of learned action at position 2
I0318 17:39:21.390202 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 3 within 2.00secs
I0318 17:39:21.390233 2212 replica.cpp:907] Replica received learned notice for position 2
I0318 17:39:21.428534 2212 replica.cpp:384] Persisting action (19 bytes) to leveldb took 36.63ms
I0318 17:39:21.428630 2212 replica.cpp:967] Persisted action at 2
I0318 17:39:21.429775 2212 replica.cpp:912] Replica learned APPEND action at position 2
I0318 17:39:21.430204 2212 replica.cpp:807] Replica received write request for position 3
I0318 17:39:21.501492 2212 replica.cpp:384] Persisting action (17 bytes) to leveldb took 70.80ms
I0318 17:39:21.501531 2212 replica.cpp:967] Persisted action at 3
I0318 17:39:21.503113 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 3
I0318 17:39:21.503412 2211 replica.cpp:807] Replica received write request for position 3
I0318 17:39:21.565305 2211 replica.cpp:384] Persisting action (19 bytes) to leveldb took 61.47ms
I0318 17:39:21.565351 2211 replica.cpp:967] Persisted action at 3
I0318 17:39:21.566685 2065 coordinator.cpp:384] Telling other replicas of learned action at position 3
I0318 17:39:21.615103 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 4 within 2.00secs
I0318 17:39:21.615144 2215 replica.cpp:907] Replica received learned notice for position 3
I0318 17:39:21.701895 2215 replica.cpp:384] Persisting action (19 bytes) to leveldb took 61.67ms
I0318 17:39:21.701935 2215 replica.cpp:967] Persisted action at 3
I0318 17:39:21.702776 2215 replica.cpp:912] Replica learned APPEND action at position 3
I0318 17:39:21.731740 2215 replica.cpp:807] Replica received write request for position 4
I0318 17:39:21.789510 2215 replica.cpp:384] Persisting action (17 bytes) to leveldb took 57.01ms
I0318 17:39:21.789600 2215 replica.cpp:967] Persisted action at 4
I0318 17:39:21.790376 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 4
I0318 17:39:21.798563 2212 replica.cpp:807] Replica received write request for position 4
I0318 17:39:21.834048 2212 replica.cpp:384] Persisting action (19 bytes) to leveldb took 34.67ms
I0318 17:39:21.834094 2212 replica.cpp:967] Persisted action at 4
I0318 17:39:21.835016 2065 coordinator.cpp:384] Telling other replicas of learned action at position 4
I0318 17:39:21.835372 2216 replica.cpp:907] Replica received learned notice for position 4
I0318 17:39:21.835361 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 5 within 2.00secs
I0318 17:39:21.864500 2216 replica.cpp:384] Persisting action (19 bytes) to leveldb took 28.70ms
I0318 17:39:21.864548 2216 replica.cpp:967] Persisted action at 4
I0318 17:39:21.866053 2216 replica.cpp:912] Replica learned APPEND action at position 4
I0318 17:39:21.867081 2216 replica.cpp:807] Replica received write request for position 5
I0318 17:39:21.947774 2216 replica.cpp:384] Persisting action (17 bytes) to leveldb took 31.09ms
I0318 17:39:21.947835 2216 replica.cpp:967] Persisted action at 5
I0318 17:39:21.978857 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 5
I0318 17:39:21.985807 2214 replica.cpp:807] Replica received write request for position 5
I0318 17:39:22.014461 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 28.48ms
I0318 17:39:22.014509 2214 replica.cpp:967] Persisted action at 5
I0318 17:39:22.015903 2065 coordinator.cpp:384] Telling other replicas of learned action at position 5
I0318 17:39:22.016592 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 6 within 2.00secs
I0318 17:39:22.016633 2214 replica.cpp:907] Replica received learned notice for position 5
I0318 17:39:22.174883 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 76.78ms
I0318 17:39:22.174924 2214 replica.cpp:967] Persisted action at 5
I0318 17:39:22.175294 2214 replica.cpp:912] Replica learned APPEND action at position 5
I0318 17:39:22.175734 2214 replica.cpp:807] Replica received write request for position 6
I0318 17:39:22.206050 2214 replica.cpp:384] Persisting action (17 bytes) to leveldb took 29.80ms
I0318 17:39:22.206215 2214 replica.cpp:967] Persisted action at 6
I0318 17:39:22.206856 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 6
I0318 17:39:22.207182 2214 replica.cpp:807] Replica received write request for position 6
I0318 17:39:22.259229 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 51.73ms
I0318 17:39:22.259402 2214 replica.cpp:967] Persisted action at 6
I0318 17:39:22.259989 2065 coordinator.cpp:384] Telling other replicas of learned action at position 6
I0318 17:39:22.260226 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 7 within 2.00secs
I0318 17:39:22.260269 2214 replica.cpp:907] Replica received learned notice for position 6
I0318 17:39:22.297613 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 36.45ms
I0318 17:39:22.297778 2214 replica.cpp:967] Persisted action at 6
I0318 17:39:22.298118 2214 replica.cpp:912] Replica learned APPEND action at position 6
I0318 17:39:22.298563 2214 replica.cpp:807] Replica received write request for position 7
I0318 17:39:22.384413 2214 replica.cpp:384] Persisting action (17 bytes) to leveldb took 85.38ms
I0318 17:39:22.384498 2214 replica.cpp:967] Persisted action at 7
I0318 17:39:22.419061 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 7
I0318 17:39:22.419374 2214 replica.cpp:807] Replica received write request for position 7
I0318 17:39:22.447576 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 28.01ms
I0318 17:39:22.447621 2214 replica.cpp:967] Persisted action at 7
I0318 17:39:22.497864 2065 coordinator.cpp:384] Telling other replicas of learned action at position 7
I0318 17:39:22.564687 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 8 within 2.00secs
I0318 17:39:22.564715 2211 replica.cpp:907] Replica received learned notice for position 7
I0318 17:39:22.622426 2211 replica.cpp:384] Persisting action (19 bytes) to leveldb took 31.42ms
I0318 17:39:22.622468 2211 replica.cpp:967] Persisted action at 7
I0318 17:39:22.666226 2211 replica.cpp:912] Replica learned APPEND action at position 7
I0318 17:39:22.676942 2211 replica.cpp:807] Replica received write request for position 8
I0318 17:39:22.755686 2211 replica.cpp:384] Persisting action (17 bytes) to leveldb took 47.75ms
I0318 17:39:22.755722 2211 replica.cpp:967] Persisted action at 8
I0318 17:39:22.787497 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 8
I0318 17:39:22.826035 2214 replica.cpp:807] Replica received write request for position 8
I0318 17:39:22.872356 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 46.09ms
I0318 17:39:22.872402 2214 replica.cpp:967] Persisted action at 8
I0318 17:39:22.901646 2065 coordinator.cpp:384] Telling other replicas of learned action at position 8
I0318 17:39:22.914504 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 9 within 2.00secs
I0318 17:39:22.914573 2213 replica.cpp:907] Replica received learned notice for position 8
I0318 17:39:22.967422 2213 replica.cpp:384] Persisting action (19 bytes) to leveldb took 51.67ms
I0318 17:39:22.967468 2213 replica.cpp:967] Persisted action at 8
I0318 17:39:22.997447 2213 replica.cpp:912] Replica learned APPEND action at position 8
I0318 17:39:23.006012 2213 replica.cpp:807] Replica received write request for position 9
I0318 17:39:23.068090 2213 replica.cpp:384] Persisting action (17 bytes) to leveldb took 61.15ms
I0318 17:39:23.068132 2213 replica.cpp:967] Persisted action at 9
I0318 17:39:23.085082 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 9
I0318 17:39:23.114475 2215 replica.cpp:807] Replica received write request for position 9
I0318 17:39:23.192199 2215 replica.cpp:384] Persisting action (19 bytes) to leveldb took 77.50ms
I0318 17:39:23.192239 2215 replica.cpp:967] Persisted action at 9
I0318 17:39:23.192796 2065 coordinator.cpp:384] Telling other replicas of learned action at position 9
I0318 17:39:23.193119 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 10 within 2.00secs
I0318 17:39:23.193168 2216 replica.cpp:907] Replica received learned notice for position 9
I0318 17:39:23.255472 2216 replica.cpp:384] Persisting action (19 bytes) to leveldb took 61.47ms
I0318 17:39:23.274919 2216 replica.cpp:967] Persisted action at 9
I0318 17:39:23.284596 2216 replica.cpp:912] Replica learned APPEND action at position 9
I0318 17:39:23.316602 2216 replica.cpp:807] Replica received write request for position 10
I0318 17:39:23.372073 2216 replica.cpp:384] Persisting action (18 bytes) to leveldb took 55.02ms
I0318 17:39:23.391677 2216 replica.cpp:967] Persisted action at 10
I0318 17:39:23.392331 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 10
I0318 17:39:23.392777 2212 replica.cpp:807] Replica received write request for position 10
I0318 17:39:23.441594 2212 replica.cpp:384] Persisting action (20 bytes) to leveldb took 48.52ms
I0318 17:39:23.441644 2212 replica.cpp:967] Persisted action at 10
I0318 17:39:23.442253 2065 coordinator.cpp:384] Telling other replicas of learned action at position 10
I0318 17:39:23.442487 2065 coordinator.cpp:225] Coordinator attempting to write TRUNCATE action at position 11 within 2.00secs
I0318 17:39:23.442514 2212 replica.cpp:907] Replica received learned notice for position 10
I0318 17:39:23.472084 2212 replica.cpp:384] Persisting action (20 bytes) to leveldb took 28.65ms
I0318 17:39:23.472136 2212 replica.cpp:967] Persisted action at 10
I0318 17:39:23.472494 2212 replica.cpp:912] Replica learned APPEND action at position 10
I0318 17:39:23.489094 2212 replica.cpp:807] Replica received write request for position 11
I0318 17:39:23.517138 2212 replica.cpp:384] Persisting action (16 bytes) to leveldb took 27.62ms
I0318 17:39:23.517174 2212 replica.cpp:967] Persisted action at 11
I0318 17:39:23.518193 2065 coordinator.cpp:316] Coordinator attempting to commit TRUNCATE action at position 11
I0318 17:39:23.518543 2216 replica.cpp:807] Replica received write request for position 11
I0318 17:39:23.547039 2216 replica.cpp:384] Persisting action (18 bytes) to leveldb took 28.20ms
I0318 17:39:23.547112 2216 replica.cpp:432] Deleting ~7 keys from leveldb took 33.56us
I0318 17:39:23.547894 2216 replica.cpp:967] Persisted action at 11
I0318 17:39:23.548555 2065 coordinator.cpp:384] Telling other replicas of learned action at position 11
I0318 17:39:23.548835 2214 replica.cpp:907] Replica received learned notice for position 11
I0318 17:39:23.575451 2214 replica.cpp:384] Persisting action (18 bytes) to leveldb took 26.23ms
I0318 17:39:23.575530 2214 replica.cpp:432] Deleting ~7 keys from leveldb took 26.41us
I0318 17:39:23.589777 2214 replica.cpp:967] Persisted action at 11
I0318 17:39:23.656669 2214 replica.cpp:912] Replica learned TRUNCATE action at position 11
I0318 17:39:23.868880 2065 replica.cpp:229] Opened db in 319.99ms
I0318 17:39:23.886543 2065 replica.cpp:236] Compacted db in 17.62ms
I0318 17:39:23.886876 2065 replica.cpp:252] Created db iterator in 4.79us
I0318 17:39:23.905668 2065 replica.cpp:258] Seeked to beginning of db in 700.00ns
I0318 17:39:23.906103 2065 replica.cpp:309] Iterated through 0 keys in the db in 666.00ns
I0318 17:39:23.906604 2065 replica.cpp:1039] Replica recovered with log positions 0 -> 0 and holes { 0 } and unlearned { }
I0318 17:39:23.907198 2065 coordinator.cpp:60] Coordinator attempting to get elected within 2.00secs
I0318 17:39:23.908005 2212 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:23.908045 2212 replica.cpp:780] Replica denying promise request for 1
I0318 17:39:23.908112 2216 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:23.908777 2065 coordinator.cpp:60] Coordinator attempting to get elected within 2.00secs
I0318 17:39:23.977831 2216 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 68.85ms
I0318 17:39:23.977879 2216 replica.cpp:952] Persisted promise to 1
I0318 17:39:24.004199 2212 replica.cpp:776] Replica received implicit promise request for 2
I0318 17:39:24.004310 2214 replica.cpp:776] Replica received implicit promise request for 2
I0318 17:39:24.060505 2212 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 56.20ms
I0318 17:39:24.138818 2212 replica.cpp:952] Persisted promise to 2
I0318 17:39:24.200693 2214 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 97.77ms
I0318 17:39:24.247083 2214 replica.cpp:952] Persisted promise to 2
I0318 17:39:24.248322 2065 coordinator.cpp:114] Coordinator elected, attempting to fill missing positions
I0318 17:39:24.248646 2065 coordinator.cpp:395] Coordinator attempting to fill position 0 in the log
I0318 17:39:24.249182 2212 replica.cpp:704] Replica received explicit promise request for 2 for position 0
E0318 17:39:24.249461 2212 replica.cpp:737] Error getting log record at 0: Attempted to read truncated position
I0318 17:39:24.249285 2216 replica.cpp:704] Replica received explicit promise request for 2 for position 0
I0318 17:39:24.275899 2216 replica.cpp:384] Persisting action (8 bytes) to leveldb took 25.06ms
I0318 17:39:24.275997 2216 replica.cpp:967] Persisted action at 0
I0318 17:39:24.316141 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 0
I0318 17:39:24.316447 2217 replica.cpp:807] Replica received write request for position 0
I0318 17:39:24.316782 2217 replica.cpp:469] Reading position from leveldb took 13.97us
I0318 17:39:24.338377 2217 replica.cpp:384] Persisting action (16 bytes) to leveldb took 21.16ms
I0318 17:39:24.338417 2217 replica.cpp:967] Persisted action at 0
I0318 17:39:24.376107 2065 coordinator.cpp:384] Telling other replicas of learned action at position 0
I0318 17:39:24.376474 2065 coordinator.cpp:395] Coordinator attempting to fill position 1 in the log
I0318 17:39:24.376494 2216 replica.cpp:907] Replica received learned notice for position 0
I0318 17:39:24.377281 2213 replica.cpp:704] Replica received explicit promise request for 2 for position 1
I0318 17:39:24.419559 2213 replica.cpp:384] Persisting action (8 bytes) to leveldb took 41.71ms
I0318 17:39:24.433719 2213 replica.cpp:967] Persisted action at 1
I0318 17:39:24.444907 2216 replica.cpp:384] Persisting action (16 bytes) to leveldb took 67.53ms
I0318 17:39:24.493103 2216 replica.cpp:967] Persisted action at 0
I0318 17:39:24.513695 2216 replica.cpp:912] Replica learned NOP action at position 0
I0318 17:39:24.521932 2216 replica.cpp:704] Replica received explicit promise request for 2 for position 1
E0318 17:39:24.522907 2216 replica.cpp:737] Error getting log record at 1: Attempted to read truncated position
I0318 17:39:24.523174 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 1
I0318 17:39:24.626761 2212 replica.cpp:807] Replica received write request for position 1
I0318 17:39:24.627442 2212 replica.cpp:469] Reading position from leveldb took 15.50us
I0318 17:39:24.646486 2212 replica.cpp:384] Persisting action (16 bytes) to leveldb took 18.63ms
I0318 17:39:24.646529 2212 replica.cpp:967] Persisted action at 1
I0318 17:39:24.647157 2065 coordinator.cpp:384] Telling other replicas of learned action at position 1
I0318 17:39:24.647495 2065 coordinator.cpp:395] Coordinator attempting to fill position 2 in the log
I0318 17:39:24.647512 2215 replica.cpp:907] Replica received learned notice for position 1
I0318 17:39:24.648288 2217 replica.cpp:704] Replica received explicit promise request for 2 for position 2
I0318 17:39:24.674885 2217 replica.cpp:384] Persisting action (8 bytes) to leveldb took 26.03ms
I0318 17:39:24.675313 2217 replica.cpp:967] Persisted action at 2
I0318 17:39:24.696563 2215 replica.cpp:384] Persisting action (16 bytes) to leveldb took 48.22ms
I0318 17:39:24.697736 2215 replica.cpp:967] Persisted action at 1
I0318 17:39:24.698169 2215 replica.cpp:912] Replica learned NOP action at position 1
I0318 17:39:24.698647 2215 replica.cpp:704] Replica received explicit promise request for 2 for position 2
E0318 17:39:24.699131 2215 replica.cpp:737] Error getting log record at 2: Attempted to read truncated position
I0318 17:39:24.699480 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 2
I0318 17:39:24.700716 2213 replica.cpp:807] Replica received write request for position 2
I0318 17:39:24.701000 2213 replica.cpp:469] Reading position from leveldb took 14.62us
I0318 17:39:24.725589 2213 replica.cpp:384] Persisting action (16 bytes) to leveldb took 24.10ms
I0318 17:39:24.725632 2213 replica.cpp:967] Persisted action at 2
I0318 17:39:24.776113 2065 coordinator.cpp:384] Telling other replicas of learned action at position 2
I0318 17:39:24.776305 2065 coordinator.cpp:395] Coordinator attempting to fill position 3 in the log
I0318 17:39:24.776367 2212 replica.cpp:907] Replica received learned notice for position 2
I0318 17:39:24.777163 2217 replica.cpp:704] Replica received explicit promise request for 2 for position 3
I0318 17:39:24.804782 2212 replica.cpp:384] Persisting action (16 bytes) to leveldb took 27.58ms
I0318 17:39:24.833741 2212 replica.cpp:967] Persisted action at 2
I0318 17:39:24.850782 2212 replica.cpp:912] Replica learned NOP action at position 2
I0318 17:39:24.842015 2217 replica.cpp:384] Persisting action (8 bytes) to leveldb took 64.33ms
I0318 17:39:24.863893 2217 replica.cpp:967] Persisted action at 3
I0318 17:39:24.863459 2212 replica.cpp:704] Replica received explicit promise request for 2 for position 3
E0318 17:39:24.864861 2212 replica.cpp:737] Error getting log record at 3: Attempted to read truncated position
I0318 17:39:24.865175 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 3
I0318 17:39:24.866509 2210 replica.cpp:807] Replica received write request for position 3
I0318 17:39:24.866920 2210 replica.cpp:469] Reading position from leveldb took 15.49us
I0318 17:39:24.892238 2210 replica.cpp:384] Persisting action (16 bytes) to leveldb took 24.87ms
I0318 17:39:24.892277 2210 replica.cpp:967] Persisted action at 3
I0318 17:39:24.932402 2065 coordinator.cpp:384] Telling other replicas of learned action at position 3
I0318 17:39:24.932672 2065 coordinator.cpp:395] Coordinator attempting to fill position 4 in the log
I0318 17:39:24.932694 2216 replica.cpp:907] Replica received learned notice for position 3
I0318 17:39:24.933665 2211 replica.cpp:704] Replica received explicit promise request for 2 for position 4
I0318 17:39:24.963003 2216 replica.cpp:384] Persisting action (16 bytes) to leveldb took 29.43ms
I0318 17:39:24.985409 2216 replica.cpp:967] Persisted action at 3
I0318 17:39:25.000283 2211 replica.cpp:384] Persisting action (8 bytes) to leveldb took 66.23ms
I0318 17:39:25.021823 2211 replica.cpp:967] Persisted action at 4
I0318 17:39:25.000675 2216 replica.cpp:912] Replica learned NOP action at position 3
I0318 17:39:25.023488 2216 replica.cpp:704] Replica received explicit promise request for 2 for position 4
E0318 17:39:25.023929 2216 replica.cpp:737] Error getting log record at 4: Attempted to read truncated position
I0318 17:39:25.024188 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 4
I0318 17:39:25.025483 2211 replica.cpp:807] Replica received write request for position 4
I0318 17:39:25.025804 2211 replica.cpp:469] Reading position from leveldb took 11.48us
I0318 17:39:25.100253 2211 replica.cpp:384] Persisting action (16 bytes) to leveldb took 73.98ms
I0318 17:39:25.100343 2211 replica.cpp:967] Persisted action at 4
I0318 17:39:25.100986 2065 coordinator.cpp:384] Telling other replicas of learned action at position 4
I0318 17:39:25.101233 2065 coordinator.cpp:395] Coordinator attempting to fill position 5 in the log
I0318 17:39:25.101241 2216 replica.cpp:907] Replica received learned notice for position 4
I0318 17:39:25.102088 2217 replica.cpp:704] Replica received explicit promise request for 2 for position 5
I0318 17:39:25.146381 2217 replica.cpp:384] Persisting action (8 bytes) to leveldb took 43.10ms
I0318 17:39:25.146790 2217 replica.cpp:967] Persisted action at 5
I0318 17:39:25.225152 2216 replica.cpp:384] Persisting action (16 bytes) to leveldb took 123.00ms
I0318 17:39:25.225203 2216 replica.cpp:967] Persisted action at 4
I0318 17:39:25.225600 2216 replica.cpp:912] Replica learned NOP action at position 4
I0318 17:39:25.226001 2216 replica.cpp:704] Replica received explicit promise request for 2 for position 5
E0318 17:39:25.226481 2216 replica.cpp:737] Error getting log record at 5: Attempted to read truncated position
I0318 17:39:25.226811 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 5
I0318 17:39:25.255215 2212 replica.cpp:807] Replica received write request for position 5
I0318 17:39:25.255571 2212 replica.cpp:469] Reading position from leveldb took 15.45us
I0318 17:39:25.281355 2212 replica.cpp:384] Persisting action (16 bytes) to leveldb took 25.36ms
I0318 17:39:25.281442 2212 replica.cpp:967] Persisted action at 5
I0318 17:39:25.282049 2065 coordinator.cpp:384] Telling other replicas of learned action at position 5
I0318 17:39:25.282373 2065 coordinator.cpp:395] Coordinator attempting to fill position 6 in the log
I0318 17:39:25.282457 2213 replica.cpp:907] Replica received learned notice for position 5
I0318 17:39:25.283192 2211 replica.cpp:704] Replica received explicit promise request for 2 for position 6
I0318 17:39:25.349560 2213 replica.cpp:384] Persisting action (16 bytes) to leveldb took 27.89ms
I0318 17:39:25.349601 2213 replica.cpp:967] Persisted action at 5
I0318 17:39:25.371661 2213 replica.cpp:912] Replica learned NOP action at position 5
I0318 17:39:25.387817 2211 replica.cpp:384] Persisting action (8 bytes) to leveldb took 65.67ms
I0318 17:39:25.410442 2211 replica.cpp:967] Persisted action at 6
I0318 17:39:25.388641 2213 replica.cpp:704] Replica received explicit promise request for 2 for position 6
E0318 17:39:25.438215 2213 replica.cpp:737] Error getting log record at 6: Attempted to read truncated position
I0318 17:39:25.438477 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 6
I0318 17:39:25.439656 2211 replica.cpp:807] Replica received write request for position 6
I0318 17:39:25.440001 2211 replica.cpp:469] Reading position from leveldb took 9.94us
I0318 17:39:25.475301 2211 replica.cpp:384] Persisting action (16 bytes) to leveldb took 34.76ms
I0318 17:39:25.475419 2211 replica.cpp:967] Persisted action at 6
I0318 17:39:25.476133 2065 coordinator.cpp:384] Telling other replicas of learned action at position 6
I0318 17:39:25.476287 2065 coordinator.cpp:395] Coordinator attempting to fill position 7 in the log
I0318 17:39:25.476330 2214 replica.cpp:907] Replica received learned notice for position 6
I0318 17:39:25.477110 2217 replica.cpp:704] Replica received explicit promise request for 2 for position 7
I0318 17:39:25.507810 2214 replica.cpp:384] Persisting action (16 bytes) to leveldb took 30.60ms
I0318 17:39:25.507884 2214 replica.cpp:967] Persisted action at 6
I0318 17:39:25.532029 2214 replica.cpp:912] Replica learned NOP action at position 6
I0318 17:39:25.531579 2217 replica.cpp:384] Persisting action (8 bytes) to leveldb took 53.74ms
I0318 17:39:25.563362 2217 replica.cpp:967] Persisted action at 7
I0318 17:39:25.532907 2214 replica.cpp:704] Replica received explicit promise request for 2 for position 7
I0318 17:39:25.587690 2214 replica.cpp:469] Reading position from leveldb took 24.29us
I0318 17:39:25.621086 2214 replica.cpp:384] Persisting action (19 bytes) to leveldb took 33.01ms
I0318 17:39:25.621126 2214 replica.cpp:967] Persisted action at 7
I0318 17:39:25.621861 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 7
I0318 17:39:25.622117 2212 replica.cpp:807] Replica received write request for position 7
I0318 17:39:25.622424 2212 replica.cpp:469] Reading position from leveldb took 11.90us
I0318 17:39:25.639507 2212 replica.cpp:384] Persisting action (19 bytes) to leveldb took 16.62ms
I0318 17:39:25.639536 2212 replica.cpp:967] Persisted action at 7
I0318 17:39:25.640063 2065 coordinator.cpp:384] Telling other replicas of learned action at position 7
I0318 17:39:25.640403 2065 coordinator.cpp:395] Coordinator attempting to fill position 8 in the log
I0318 17:39:25.640413 2212 replica.cpp:907] Replica received learned notice for position 7
I0318 17:39:25.641167 2211 replica.cpp:704] Replica received explicit promise request for 2 for position 8
I0318 17:39:25.666064 2211 replica.cpp:384] Persisting action (8 bytes) to leveldb took 24.19ms
I0318 17:39:25.688231 2211 replica.cpp:967] Persisted action at 8
I0318 17:39:25.689807 2212 replica.cpp:384] Persisting action (19 bytes) to leveldb took 48.52ms
I0318 17:39:25.691958 2212 replica.cpp:967] Persisted action at 7
I0318 17:39:25.729842 2212 replica.cpp:912] Replica learned APPEND action at position 7
I0318 17:39:25.730283 2212 replica.cpp:704] Replica received explicit promise request for 2 for position 8
I0318 17:39:25.730762 2212 replica.cpp:469] Reading position from leveldb took 12.15us
I0318 17:39:25.757675 2212 replica.cpp:384] Persisting action (19 bytes) to leveldb took 26.44ms
I0318 17:39:25.757715 2212 replica.cpp:967] Persisted action at 8
I0318 17:39:25.759368 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 8
I0318 17:39:25.759640 2216 replica.cpp:807] Replica received write request for position 8
I0318 17:39:25.759893 2216 replica.cpp:469] Reading position from leveldb took 10.53us
I0318 17:39:25.820720 2216 replica.cpp:384] Persisting action (19 bytes) to leveldb took 60.36ms
I0318 17:39:25.820758 2216 replica.cpp:967] Persisted action at 8
I0318 17:39:25.821636 2065 coordinator.cpp:384] Telling other replicas of learned action at position 8
I0318 17:39:25.822064 2065 coordinator.cpp:395] Coordinator attempting to fill position 9 in the log
I0318 17:39:25.822101 2210 replica.cpp:907] Replica received learned notice for position 8
I0318 17:39:25.822845 2211 replica.cpp:704] Replica received explicit promise request for 2 for position 9
I0318 17:39:25.871033 2211 replica.cpp:384] Persisting action (8 bytes) to leveldb took 47.16ms
I0318 17:39:25.887930 2211 replica.cpp:967] Persisted action at 9
I0318 17:39:25.887518 2210 replica.cpp:384] Persisting action (19 bytes) to leveldb took 64.56ms
I0318 17:39:25.909652 2065 coordinator.cpp:498] Coordinator timed out attempting to fill position 9 in the log
tests/log_tests.cpp:1083: Failure
result is NONE
I0318 17:39:25.947976 2210 replica.cpp:967] Persisted action at 8
I0318 17:39:25.974679 2210 replica.cpp:912] Replica learned APPEND action at position 8
[ FAILED ] CoordinatorTest.TruncateLearnedFill (6188 ms)
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira