Crystal: Failing test: HTTP::Cookie::Parser expired? by max-age=0

[deiv]

Hi,

Running the spec for the std I get the next broken test:

Failures:

  1) HTTP::Cookie::Parser expired? by max-age=0
     Failure/Error: parse_set_cookie("bla=1; max-age=0").expired?.should eq true

       Expected: true
            got: false

     # spec/std/http/cookie_spec.cr:215

[straight-shoota]

Hm, that seems strange. Possible cause could be a clock issue (low resolution for example) which results in Time.utc returning the same value when parsing max-age=0 and in expired? check.

Can you please share system info and Crystal version?
And what does 10.times { puts Time.utc.to_s("%Y-%m-%d %H:%M:%S.%N") } print?

[deiv]

version: 0.34.0
system: debian unstable (inside chroot)

2020-04-10 15:42:09.023243000
2020-04-10 15:42:09.023275000
2020-04-10 15:42:09.023291000
2020-04-10 15:42:09.023310000
2020-04-10 15:42:09.023319000
2020-04-10 15:42:09.023328000
2020-04-10 15:42:09.023337000
2020-04-10 15:42:09.023346000
2020-04-10 15:42:09.023355000
2020-04-10 15:42:09.023365000

[deiv]

Hi,

failed again:

Failures:

  1) HTTP::Cookie::Parser expired? by max-age=0
     Failure/Error: parse_set_cookie("bla=1; max-age=0").expired?.should eq true

       Expected: true
            got: false

     # spec/std/http/cookie_spec.cr:215

Finished in 30.41 seconds
9205 examples, 1 failures, 0 errors, 7 pending

[asterite]

Could you modify the spec so it shows why it fails? Specifically, print the current time and the cookie expiration time.

[RX14]

Is it a random failure or every time? @deiv

If it's non-deterministic it's probably an issue with the TSC counter (and thus all non-monotonic time) becoming non-monotonic due to spectre mitigations.

We should wait a small delta in the range of milliseconds before checking that it's expired, or apply a small negative delta to max-age, or treat max-age=0 differently.

[deiv]

Hi,

Totally reproducible (as I say. at least in a Debian unstable chroot).

If I add the next code to the spec, the spec passes:

- parse_set_cookie("bla=1; max-age=0").expired?.should eq true
+ cookie = parse_set_cookie("bla=1; max-age=0")
+ puts "cookie.expires"
+ puts cookie.expires.not_nil!.to_utc.to_s("%Y-%m-%d %H:%M:%S.%N")
+ puts "Time.utc"
+ puts Time.utc.to_s("%Y-%m-%d %H:%M:%S.%N")
+ cookie.expired?.should eq true
- parse_set_cookie("bla=1; max-age=0").expired?.should eq true

buiid log:

expired?
by max-age=0cookie.expires
2020-04-13 13:28:48.817609000
Time.utc
2020-04-13 13:28:48.817615000

Seems that the added code is letting the clock advance ...

Leaving untouched, the spec fails always.

[asterite]

What's the output of this:

puts Time.utc
cookie = parse_set_cookie("bla=1; max-age=0")
puts cookie.expires

[deiv]

@asterite

That's will give resolution until second not ? Is that you want ?

I forgot to say: If I run only the specific spec file inside the chroot, in any condifition it pass... I have to run all the std specs batery to expect the fail

[asterite]

Until we can understand why it fails, that is, until we can show what time values are failing, there's nothing we can do here.

[deiv]

@asterite

Eg: If I eval ./bin/crystal eval "puts Time.utc" it gives 2020-04-13 14:58:36 UTC, so we can only see the resolution until seconds, and there is some formatting execution meamwhile

Something like ?:

timeee = Time.utc
cookie = parse_set_cookie("bla=1; max-age=0")
puts timeee.nanosecond
puts cookie.expires.nanosecond

Taking care that we are in the same second ...

[asterite]

Yes, that sounds good. What's the output?

[asterite]

Maybe not just nanosecond, the formatting you used before is fine. But done like in your last snippet.

[deiv]

@asterite

yep, with the formatting better (nanoseconds was becuse the nerves of the live hehe)

Just running... waiting for the completion

[deiv]

Spec passed with:

cookie.expires

2020-04-13 16:10:28.754727000
Time.utc
2020-04-13 16:10:28.754726000

[RX14]

It's probably just the < instead of <= here: https://github.com/crystal-lang/crystal/blob/master/src/http/cookie.cr#L66

Time.utc easilly returns the same value multiple times: https://carc.in/#/r/8vrg

[asterite]

It's probably just the < instead of <= here: https://github.com/crystal-lang/crystal/blob/master/src/http/cookie.cr#L66

👍

I'd also write it like Time.utc >= e

[RX14]

I havent actually tested whether #9061 fixes this, so I'd like word if I was correct @deiv

[deiv]

@RX14

For me, with this change, now the spec pass