#24555 closed defect (fixed)

Bug: tor_gmtime_r overflow - gmtime(9223372036854775807) failed with error No error

Reported by: s7r Owned by:
Priority: Medium Milestone: Tor: 0.3.3.x-final
Component: Core Tor/Tor Version: Tor: unspecified
Severity: Normal Keywords: integer-overflow time-overflow tor-relay 2038-problem
Cc: Actual Points:
Parent ID: #18480 Points:
Reviewer: Sponsor:

Description

It's here. FreeBSD 10.3 running 0.3.3.0-alpha-dev (git-e8a6a6635b26c327).

Setting parent ticket the one with all time functions with undefined behavior.

Relay:

Dec 06 04:10:15.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 04:10:15.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 09:07:16.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 11:04:16.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 11:04:16.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 12:15:25.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 15:24:16.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 17:15:17.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 06 20:16:16.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327
Dec 07 12:09:37.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)
Dec 07 13:03:18.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev e8a6a6635b26c327)

Bridge:

Dec 06 03:34:15.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 1969d573637ee6f9)
Dec 06 03:34:15.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 1969d573637ee6f9)
Dec 06 09:54:15.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 1969d573637ee6f9)
Dec 06 09:54:15.000 [warn] correct_tm: Bug: gmtime(9223372036854775807) failed with error No error: 0: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 1969d573637ee6f9)

Time on the system is accurate and synced with ntp permanently.

Child Tickets

Change History (14)

comment:1 Changed 19 months ago by nickm

Interesting that 9223372036854775807 is 0x7fffffffffffffff (INT64_MAX).

comment:2 Changed 19 months ago by dgoulet

Milestone: Tor: 0.3.3.x-finalTor: 0.3.2.x-final

On Linux 4.4.0-101, I got this multiple times in the last couple days.

Dec 09 08:10:39.718 [warn] correct_tm(): Bug: gmtime(9223372036854775807) failed with error Value too large for defined data type: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 44010c6fc11608b1)

comment:3 Changed 19 months ago by dgoulet

Oups... I put that in 032 but maybe this is in master actually? What did we get in that might have touched the time values?

comment:4 Changed 19 months ago by arma

I hit this too just now on my fast relay.

My only hint is that maybe I was out of file descriptors at the time.

comment:5 Changed 19 months ago by nickm

Milestone: Tor: 0.3.2.x-finalTor: 0.3.3.x-final

comment:6 Changed 19 months ago by arma

My relay hits this log message many times a day still.

I don't think it's running out of file descriptors.

I guess I should turn it into an assert, and get us a stack trace.

comment:7 Changed 19 months ago by arma

#2  0x00007f418dd5fbe6 in correct_tm (islocal=0, timep=0x7fff2d162b18, 
    resultbuf=<value optimized out>, r=<value optimized out>)
    at src/common/compat.c:2974
#3  0x00007f418dd72c5c in format_iso_time (
    buf=0x7fff2d162c60 "2018-01-13 02:00:00", t=9223372036854775807)
    at src/common/util.c:1777
#4  0x00007f418dc767e6 in update_consensus_router_descriptor_downloads (
    now=1515201474, is_vote=756427840, consensus=0x7f419edbb550)
    at src/or/routerlist.c:5217
#5  0x00007f418dc76c80 in update_all_descriptor_downloads (now=1515201474)
    at src/or/routerlist.c:4562
#6  0x00007f418dc24660 in directory_info_has_arrived (now=1515201474, 
    from_cache=0, suppress_logs=0) at src/or/main.c:1116
#7  0x00007f418dd08b6d in handle_response_fetch_consensus (
    conn=<value optimized out>) at src/or/directory.c:2631
#8  connection_dir_client_reached_eof (conn=<value optimized out>)
    at src/or/directory.c:2487
#9  connection_dir_reached_eof (conn=<value optimized out>)
    at src/or/directory.c:3357
#10 0x00007f418dcddd15 in connection_reached_eof (conn=0x7f41a74f6970)
    at src/or/connection.c:4696
#11 connection_handle_read_impl (conn=0x7f41a74f6970)
    at src/or/connection.c:3503
#12 connection_handle_read (conn=0x7f41a74f6970) at src/or/connection.c:3516
#13 0x00007f418dc27811 in conn_read_callback (fd=<value optimized out>, 
    event=<value optimized out>, _conn=0x7f41a74f6970) at src/or/main.c:861
#14 0x00007f418ddd3414 in event_persist_closure ()
#15 0x00007f418ddd3725 in event_process_active_single_queue ()
#16 0x00007f418ddd3db5 in event_process_active ()
#17 0x00007f418ddd4519 in event_base_loop ()
#18 0x00007f418dc24a8b in run_main_loop_once () at src/or/main.c:2780
#19 run_main_loop_until_done () at src/or/main.c:2852
#20 do_main_loop () at src/or/main.c:2735
#21 0x00007f418dc2506b in tor_run_main (tor_cfg=<value optimized out>)
    at src/or/main.c:4016
#22 0x00007f418dc1f953 in tor_main (argc=3, argv=0x7fff2d163318)
    at src/or/tor_api.c:84
#23 0x00007f418dc1f7e9 in main (argc=<value optimized out>, 
    argv=<value optimized out>) at src/or/tor_main.c:22
(gdb) up
#3  0x00007f418dd72c5c in format_iso_time (
    buf=0x7fff2d162c60 "2018-01-13 02:00:00", t=9223372036854775807)
    at src/common/util.c:1777
1777      strftime(buf, ISO_TIME_LEN+1, "%Y-%m-%d %H:%M:%S", tor_gmtime_r(&t, &tm));
(gdb) print t
$3 = 9223372036854775807
(gdb) up
#4  0x00007f418dc767e6 in update_consensus_router_descriptor_downloads (
    now=1515201474, is_vote=756427840, consensus=0x7f419edbb550)
    at src/or/routerlist.c:5217
5217            format_iso_time(time_cert_expires, ri->cert_expiration_time);
(gdb) print *ri
value has been optimized out
(gdb) print ri->cert_expiration_time
value has been optimized out
(gdb) print time_cert_expires
$4 = "2018-01-13 02:00:00"

Hello, what is this "is_vote=756427840"?

comment:8 Changed 19 months ago by arma

Second coredump, this time with the stuff in src/or/ compiled with -O0.

#2  0x00007f7616333be6 in correct_tm (islocal=0, timep=0x7fffc58ae128, 
    resultbuf=<value optimized out>, r=<value optimized out>)
    at src/common/compat.c:2974
#3  0x00007f7616346c5c in format_iso_time (
    buf=0x7fffc58ae270 "2018-01-28 19:00:00", t=9223372036854775807)
    at src/common/util.c:1777
#4  0x00007f761624a7e6 in update_consensus_router_descriptor_downloads (
    now=1515214793, is_vote=-980753840, consensus=0x7f7618acd450)
    at src/or/routerlist.c:5217
#5  0x00007f761624ac80 in update_all_descriptor_downloads (now=1515214793)
    at src/or/routerlist.c:4562
#6  0x00007f76161f6cb5 in launch_descriptor_fetches_callback (now=1515214793, 
    options=<value optimized out>) at src/or/main.c:1701
#7  0x00007f7616215bc0 in periodic_event_dispatch (fd=<value optimized out>, 
    what=<value optimized out>, data=0x7f7616695160) at src/or/periodic.c:52
#8  0x00007f76163a77d5 in event_process_active_single_queue ()
#9  0x00007f76163a7db5 in event_process_active ()
#10 0x00007f76163a8519 in event_base_loop ()
#11 0x00007f76161f8a8b in run_main_loop_once () at src/or/main.c:2780
#12 run_main_loop_until_done () at src/or/main.c:2852
#13 do_main_loop () at src/or/main.c:2735
#14 0x00007f76161f906b in tor_run_main (tor_cfg=<value optimized out>)
    at src/or/main.c:4016
#15 0x00007f76161f3953 in tor_main (argc=3, argv=0x7fffc58ae6b8)
    at src/or/tor_api.c:84
#16 0x00007f76161f37e9 in main (argc=<value optimized out>, 
    argv=<value optimized out>) at src/or/tor_main.c:22

"is_vote=-980753840". Sure looks like something is smashing something.

comment:9 Changed 19 months ago by arma

Third trace (tried to compile everything with -O0, to get fewer 'optimized out' issues):

#2  0x00007ff9f999abe6 in correct_tm (islocal=0, timep=0x7fff876aa808, 
    resultbuf=<value optimized out>, r=<value optimized out>)
    at src/common/compat.c:2974
#3  0x00007ff9f99adc5c in format_iso_time (
    buf=0x7fff876aa950 "2018-01-25 17:00:00", t=9223372036854775807)
    at src/common/util.c:1777
#4  0x00007ff9f98b17e6 in update_consensus_router_descriptor_downloads (
    now=1515229986, is_vote=-2023053008, consensus=0x7ffa1543b260)
    at src/or/routerlist.c:5217
#5  0x00007ff9f98b1c80 in update_all_descriptor_downloads (now=1515229986)
    at src/or/routerlist.c:4562
#6  0x00007ff9f985f660 in directory_info_has_arrived (now=1515229986, 
    from_cache=0, suppress_logs=0) at src/or/main.c:1116
#7  0x00007ff9f9943b6d in handle_response_fetch_consensus (
    conn=<value optimized out>) at src/or/directory.c:2631
#8  connection_dir_client_reached_eof (conn=<value optimized out>)
    at src/or/directory.c:2487
#9  connection_dir_reached_eof (conn=<value optimized out>)
    at src/or/directory.c:3357
#10 0x00007ff9f9918d15 in connection_reached_eof (conn=0x7ffa20acaa30)
    at src/or/connection.c:4696
#11 connection_handle_read_impl (conn=0x7ffa20acaa30)
    at src/or/connection.c:3503
#12 connection_handle_read (conn=0x7ffa20acaa30) at src/or/connection.c:3516
#13 0x00007ff9f9862811 in conn_read_callback (fd=<value optimized out>, 
    event=<value optimized out>, _conn=0x7ffa20acaa30) at src/or/main.c:861
#14 0x00007ff9f9a0e414 in event_persist_closure ()
#15 0x00007ff9f9a0e725 in event_process_active_single_queue ()
#16 0x00007ff9f9a0edb5 in event_process_active ()
#17 0x00007ff9f9a0f519 in event_base_loop ()
#18 0x00007ff9f985fa8b in run_main_loop_once () at src/or/main.c:2780
#19 run_main_loop_until_done () at src/or/main.c:2852
#20 do_main_loop () at src/or/main.c:2735
#21 0x00007ff9f986006b in tor_run_main (tor_cfg=<value optimized out>)
    at src/or/main.c:4016
#22 0x00007ff9f985a953 in tor_main (argc=3, argv=0x7fff876ab008)
    at src/or/tor_api.c:84
#23 0x00007ff9f985a7e9 in main (argc=<value optimized out>, 
    argv=<value optimized out>) at src/or/tor_main.c:22

It's clear there's some corruption going on somewhere.

comment:10 Changed 19 months ago by arma

My next hint:

Jan 06 04:13:06.931 [info] update_consensus_router_descriptor_downloads(): 2 router descriptors listed in consensus are currently in old_routers; making them current.
Jan 06 04:13:06.932 [warn] correct_tm(): Bug: gmtime(9223372036854775807) failed with error Value too large for defined data type: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 943134e886d9cef2)
Jan 06 05:48:50.264 [info] update_consensus_router_descriptor_downloads(): 15 router descriptors listed in consensus are currently in old_routers; making them current.
Jan 06 05:48:50.264 [warn] correct_tm(): Bug: gmtime(9223372036854775807) failed with error Value too large for defined data type: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 943134e886d9cef2)
Jan 06 05:48:50.269 [warn] correct_tm(): Bug: gmtime(9223372036854775807) failed with error Value too large for defined data type: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 943134e886d9cef2)
Jan 06 06:00:49.978 [info] update_consensus_router_descriptor_downloads(): 9 router descriptors listed in consensus are currently in old_routers; making them current.
Jan 06 06:00:49.981 [warn] correct_tm(): Bug: gmtime(9223372036854775807) failed with error Value too large for defined data type: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 943134e886d9cef2)
Jan 06 07:11:50.062 [info] update_consensus_router_descriptor_downloads(): 2 router descriptors listed in consensus are currently in old_routers; making them current.
Jan 06 07:11:50.063 [warn] correct_tm(): Bug: gmtime(9223372036854775807) failed with error Value too large for defined data type: Rounding down to 2037 (on Tor 0.3.3.0-alpha-dev 943134e886d9cef2)

etc

comment:11 Changed 19 months ago by arma

Ok. Getting back into the swing of this developer thing.

This bug was introduced in commit a1b0a0b9, which hasn't come out in any release yet (i.e. I don't think it's an issue in 0.3.2).

This issue is that ri->cert_expiration_time is TIME_MAX if there isn't an ed cert in the descriptor, so doing a format_iso_time() call on it before we know that router_add_to_routerlist() returned ROUTER_CERTS_EXPIRED means that we might be handing format_iso_time a TIME_MAX, which is bigger than INT32_MAX so it will warn.

comment:12 Changed 19 months ago by arma

(and the gdb issues with variables that look like they were clobbered are....just gdb bugs I guess. Fun times.)

comment:13 Changed 18 months ago by arma

Status: newneeds_review

The fix is in my bug24555 branch. It's intended to be applied to master (0.3.3).

comment:14 Changed 18 months ago by nickm

Resolution: fixed
Status: needs_reviewclosed

lgtm. merging! Thanks for tracking this down.

Note: See TracTickets for help on using tickets.