Subsets mode final status line, initial ETA weirdness

[solardiz]

$ ./john subsets=0123456789 -min-len=12 -max-len=12 a
[...]
0g 0:00:00:04 0.00% (12) (ETA: 2020-03-10 13:42) 0g/s 142490p/s 142490c/s 142490C/s 022101201001..202210000101
0g 0:00:00:05 0.00% (12) (ETA: 2020-03-02 22:45) 0g/s 142962p/s 142962c/s 142962C/s 033301311333..001303333313
0g 0:00:00:06 0.00% (12) (ETA: 2020-03-03 16:28) 0g/s 143117p/s 143117c/s 143117C/s 013303330101..001130303331
0g 0:00:00:07 0.00% (12) (ETA: 2020-03-04 10:11) 0g/s 143367p/s 143367c/s 143367C/s 013003003310..100030003330
0g 0:00:00:08 0.00% (12) (ETA: 2020-03-05 03:54) 0g/s 143554p/s 143554c/s 143554C/s 031100131110..100113110003
0g 0:00:00:09 0.00% (12) (ETA: 2020-03-03 01:55) 0g/s 143699p/s 143699c/s 143699C/s 144440001440..441040044004
0g 0:00:00:10 0.00% (12) (ETA: 2020-03-03 12:06) 0g/s 143672p/s 143815c/s 143672C/s 110144140041..044114141001
0g 0:00:00:34 0.01% (12) (ETA: 2020-03-02 21:25) 0g/s 144614p/s 144614c/s 144614C/s 040420244244..240440420440
0g 0:03:57:47 4.65% (12) (ETA: 2020-03-02 19:20) 0g/s 146992p/s 146992c/s 146992C/s 688618889691..691889686188
0g 0:08:07:26 9.59% (12) (ETA: 2020-03-02 18:52) 0g/s 147173p/s 147173c/s 147173C/s 626120664660..622400661666
0g 1:00:11:48 28.41% (12) (ETA: 2020-03-02 19:21) 0g/s 147380p/s 147380c/s 147380C/s 040347022472..034447027202
0g 1:13:18:06 43.91% (12) (ETA: 2020-03-02 19:08) 0g/s 147391p/s 147391c/s 147391C/s 408449044398..404938480944
0g 2:00:48:13 57.56% (12) (ETA: 2020-03-02 18:58) 0g/s 147449p/s 147449c/s 147449C/s 321133669296..323126616993
0g 2:23:07:26 84.13% (12) (ETA: 18:43:42) 0g/s 147504p/s 147504c/s 147504C/s 232882587832..285828382327
0g 3:06:58:50 93.36% (12) (ETA: 18:47:25) 0g/s 147516p/s 147516c/s 147516C/s 878334535844..854754333488
0g 3:12:28:02 DONE (13) (2020-03-02 18:39) 0g/s 147517p/s 147517c/s 147517C/s 575565985555..555555556987
0g 3:12:28:02 DONE (13) (2020-03-02 18:39) 0g/s 147517p/s 147517c/s 147517C/s 575565985555..555555556987
Session completed

Three really minor issues here:

1. The ETA was moving back and forth wildly in the first 10 seconds despite of fairly stable speed. Not really a usability issue, but slightly puzzling. ETA became pretty accurate after half a minute at about 0.01% searched.

2. The final status line is printed twice. (I left this unattended after seeing the 93% line. I didn't press any key when this was about to end, so that's not a possible explanation.)

3. The final status line says (13), whereas the entire run was limited to length 12.

Log excerpt:

0:00:00:00 - Candidate passwords will be buffered and tried in chunks of 8128
0:00:00:00 Proceeding with "subsets" mode
0:00:00:00 - Charset: 0123456789 size 10
0:00:00:00 - Lengths: 12-12, max. subset size 5
0:00:00:00 - No stacked rules
0:00:00:00 - Subset size 1, word length 12 (10 sets x 1 words), keyspace 10
0:00:00:00 - Subset size 2, word length 12 (45 sets x 4094 words), keyspace 184230
0:00:00:01 - Subset size 3, word length 12 (120 sets x 519156 words), keyspace 62298720
0:00:07:08 - Subset size 4, word length 12 (210 sets x 14676024 words), keyspace 3081965040
0:05:56:28 - Subset size 5, word length 12 (252 sets x 165528000 words), keyspace 41713056000
3:12:28:02 - Length 12 now fully exhausted
3:12:28:02 Session completed

The buffering of 8128 isn't large enough to explain the ETA going back and forth at first - it's small compared to the c/s rate.

[magnumripper]

Can't quite reproduce the fluctuating ETA and reviewing it I believe it's rock-solid from the mode's point of view. It correctly calculates total # candidates (for current length, but in your case it was 12 all the time) and then returns (100.0 * done / total). The actual calculation in status.c and/or conversion to "human timestamp" may be the culprit.

The other issues are fixed with #4451.

On a side note you can now say -len=12 instead of the tedious -min-len=12 -max-len=12