[musl] freeswitch and musl 1.2.x (time64 most likely)

[musl] freeswitch and musl 1.2.x (time64 most likely)

[Sebastian Kemper]

Hi all,

I put OpenWrt with musl 1.2.x on my router. freeswitch was updated a bit
in preparation for time64 libc. This snippet was added:

#if __USE_TIME_BITS64
#define TIME_T_FMT SWITCH_INT64_T_FMT
#else
#define TIME_T_FMT "ld"
#endif

And the few places where during compilation there were new warnings
(time_t related) I replaced some '%ld' with TIME_T_FMT and they
disappeared.

But now I try to start freeswitch on the router and it doesn't work. It
either just exits somehow or it segfaults. The logs on the router show
that freeswitch puts the wrong time stamps. So there must still be some
time64 problem hidden somewhere.

Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01 00:24:12.-055227 0.00% [NOTICE] switch_loadable_module.c:223 Adding Codec SPEEX 99 Speex 8000hz 20ms 1ch 24600bps
Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01 00:24:12.-066240 0.00% [CONSOLE] switch_loadable_module.c:2191 open of pre_load_modules.conf failed
Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01 00:24:12.-066240 0.00% [INFO] switch_core_sqldb.c:3593 Opening DB
Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01 00:24:12.-054973 0.00% [INFO] switch_core_sqldb.c:1842 CORE Starting SQL thread.
Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01 00:24:12.-062042 0.00% [CONSOLE] switch_loadable_module.c:1768 Successfully Loaded [mod_logfile]

This is the end of the log. And then freeswitch just disappeared.

I'm not a programmer, so looking at the code is a bit of a hurdle :D I
think that the time basics are set up in src/switch_time.c ([1]) and
src/include/switch_apr.h ([2]). I'm wondering if anybody could maybe
give these files a look and check if you see something obvious? *
(pretty please) * Or maybe give me a hint how to narrow it down? I guess
I should do a backtrace?

Kind regards,
Sebastian

[1] https://github.com/signalwire/freeswitch/blob/master/src/switch_time.c
[2] https://github.com/signalwire/freeswitch/blob/master/src/include/switch_apr.h

Re: [musl] freeswitch and musl 1.2.x (time64 most likely)

[Érico Nogueira]

On Wed Oct 27, 2021 at 7:16 PM -03, Sebastian Kemper wrote:
> Hi all,
>
> I put OpenWrt with musl 1.2.x on my router. freeswitch was updated a bit
> in preparation for time64 libc. This snippet was added:
>
> #if __USE_TIME_BITS64
> #define TIME_T_FMT SWITCH_INT64_T_FMT
> #else
> #define TIME_T_FMT "ld"
> #endif
>
> And the few places where during compilation there were new warnings
> (time_t related) I replaced some '%ld' with TIME_T_FMT and they
> disappeared.

What they should be doing is always defining TIME_T_FMT to "lld" and
casting the values to be formatted to (long long). Hardcoding platform
details like that is broken and just generally a terrible idea. I
started working on a patch, you can find it here [1].

[1] https://github.com/signalwire/freeswitch/pull/1409

However, the code does seem to be correct, so there's probably something
wrong in a place where they aren't using TIME_T_FMT.

>
> But now I try to start freeswitch on the router and it doesn't work. It
> either just exits somehow or it segfaults. The logs on the router show
> that freeswitch puts the wrong time stamps. So there must still be some
> time64 problem hidden somewhere.
>
> Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01
> 00:24:12.-055227 0.00% [NOTICE] switch_loadable_module.c:223 Adding
> Codec SPEEX 99 Speex 8000hz 20ms 1ch 24600bps
> Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01
> 00:24:12.-066240 0.00% [CONSOLE] switch_loadable_module.c:2191 open of
> pre_load_modules.conf failed
> Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01
> 00:24:12.-066240 0.00% [INFO] switch_core_sqldb.c:3593 Opening DB
> Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01
> 00:24:12.-054973 0.00% [INFO] switch_core_sqldb.c:1842 CORE Starting SQL
> thread.
> Wed Oct 27 23:44:35 2021 daemon.info freeswitch[10181]: 1970-01-01
> 00:24:12.-062042 0.00% [CONSOLE] switch_loadable_module.c:1768
> Successfully Loaded [mod_logfile]
>
> This is the end of the log. And then freeswitch just disappeared.
>
> I'm not a programmer, so looking at the code is a bit of a hurdle :D I
> think that the time basics are set up in src/switch_time.c ([1]) and
> src/include/switch_apr.h ([2]). I'm wondering if anybody could maybe
> give these files a look and check if you see something obvious? *
> (pretty please) * Or maybe give me a hint how to narrow it down? I guess
> I should do a backtrace?

Please do obtain a backtrace. A line number to look at helps plenty!

>
> Kind regards,
> Sebastian
>
> [1]
> https://github.com/signalwire/freeswitch/blob/master/src/switch_time.c
> [2]
> https://github.com/signalwire/freeswitch/blob/master/src/include/switch_apr.h

[musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Sebastian Kemper]

Am Thu, Oct 28, 2021 at 12:16:59AM +0200 schrieb Sebastian Kemper:
> I'm not a programmer, so looking at the code is a bit of a hurdle :D I
> think that the time basics are set up in src/switch_time.c ([1]) and
> src/include/switch_apr.h ([2]). I'm wondering if anybody could maybe
> give these files a look and check if you see something obvious? *
> (pretty please) * Or maybe give me a hint how to narrow it down? I guess
> I should do a backtrace?

Hi Érico, all,

Replying to my own mail as I wasn't subscribed to this list and missed
your mail. I am subscribed now.

Thanks for your reply! I applied your patch and compiled freeswitch with
"-g3". Then I got this in the backtrace:

"0x7ffeb39abac0s": not in executable format: file format not recognized
Reading symbols from /home/sk/tmp/openwrt/scripts/../staging_dir/target-mips_24kc_musl/root-ath79/usr/bin/freeswitch...
0x77f55320 in _dlstart () from /home/sk/tmp/openwrt/scripts/../staging_dir/target-mips_24kc_musl/root-ath79/lib/ld-musl-mips-sf.so.1
(gdb) c
Continuing.
warning: Could not load shared library symbols for /usr/lib/libwolfssl.so.4.8.1.d8795272.
Do you need "set solib-search-path" or "set sysroot"?
process 12090 is executing new program: /usr/bin/freeswitch
warning: Could not load shared library symbols for /usr/lib/libwolfssl.so.4.8.1.d8795272.
Do you need "set solib-search-path" or "set sysroot"?
[New Thread 12090.12100]
[New Thread 12090.12091]
[New Thread 12090.12092]
[New Thread 12090.12094]
[New Thread 12090.12097]
[New Thread 12090.12099]

Thread 2 "freeswitch" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 12090.12100]
0x77def751 in vxprintf (arg=0x76d28a88, fmt=0x77ee59aa "q'", ap=0x76d28c54, useExtended=0, func=0x77deeb45 <mout>) at src/switch_mprintf.c:689
689					for (i = n = 0; (ch = escarg[i]) != 0; i++) {
(gdb) bt
#0  0x77def751 in vxprintf (arg=0x76d28a88, fmt=0x77ee59aa "q'", ap=0x76d28c54, useExtended=0, func=0x77deeb45 <mout>) at src/switch_mprintf.c:689
#1  0x77def9eb in base_vprintf (xRealloc=0x77deeb21 <printf_realloc>, zInitBuf=<optimized out>, nInitBuf=<optimized out>, zFormat=<optimized out>,
    ap=0x76d28c4c, useInternal=0) at src/switch_mprintf.c:860
#2  0x77defaf1 in switch_mprintf (zFormat=<optimized out>) at src/switch_mprintf.c:903
#3  0x77e027d9 in switch_core_expire_registration (force=0) at src/switch_core_sqldb.c:3554
#4  switch_core_expire_registration (force=<optimized out>) at src/switch_core_sqldb.c:3539
#5  0x77e0285b in switch_core_sql_db_thread (thread=<optimized out>, obj=<optimized out>) at src/switch_core_sqldb.c:1538
#6  0x77ed01d7 in dummy_worker (opaque=0x770faf30) at threadproc/unix/thread.c:151
#7  0x77fc5014 in start (p=0x76d28d54) at src/thread/pthread_create.c:203
#8  0x77f5523c in __clone () at src/thread/mips/clone.s:33
Backtrace stopped: frame did not save the PC
(gdb)

I hope the "optimized out" items aren't too much of an issue. Would be great if you could take a look.

Thanks!

Kind regards,
Seb

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Sebastian Kemper]

Am Thu, Oct 28, 2021 at 10:21:39PM +0200 schrieb Sebastian Kemper:
>
> I hope the "optimized out" items aren't too much of an issue. Would be
> great if you could take a look.

Recompiled with "-O0", now it looks better:

0x77f55320 in _dlstart () from /home/sk/tmp/openwrt/scripts/../staging_dir/target-mips_24kc_musl/root-ath79/lib/ld-musl-mips-sf.so.1
(gdb) c
Continuing.
warning: Could not load shared library symbols for /usr/lib/libwolfssl.so.4.8.1.d8795272.
Do you need "set solib-search-path" or "set sysroot"?
process 12781 is executing new program: /usr/bin/freeswitch
warning: Could not load shared library symbols for /usr/lib/libwolfssl.so.4.8.1.d8795272.
Do you need "set solib-search-path" or "set sysroot"?
[New Thread 12781.12810]
[New Thread 12781.12782]
[New Thread 12781.12783]
[New Thread 12781.12785]
[New Thread 12781.12796]
[New Thread 12781.12809]

Thread 2 "freeswitch" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 12781.12810]
0x77d7093f in vxprintf (func=0x77d70c71 <mout>, arg=0x76c98a70, useExtended=0, fmt=0x77ee2b8e "q'", ap=0x76c98c4c) at src/switch_mprintf.c:689
689					for (i = n = 0; (ch = escarg[i]) != 0; i++) {
(gdb) bt
#0  0x77d7093f in vxprintf (func=0x77d70c71 <mout>, arg=0x76c98a70, useExtended=0, fmt=0x77ee2b8e "q'", ap=0x76c98c4c) at src/switch_mprintf.c:689
#1  0x77d70df7 in base_vprintf (xRealloc=0x77d70e6d <printf_realloc>, useInternal=0,
    zInitBuf=0x76c98acc "delete from registrations where expires > 0 and expires <= 2012362356 and hostname='", nInitBuf=350,
    zFormat=0x77ee2b40 "delete from registrations where expires > 0 and expires <= %ld and hostname='%q'", ap=0x76c98c44) at src/switch_mprintf.c:860
#2  0x77d70f81 in switch_mprintf (zFormat=0x77ee2b40 "delete from registrations where expires > 0 and expires <= %ld and hostname='%q'")
    at src/switch_mprintf.c:903
#3  0x77d8d395 in switch_core_expire_registration (force=0) at src/switch_core_sqldb.c:3554
#4  0x77d85975 in switch_core_sql_db_thread (thread=0x770b9ee0, obj=0x0) at src/switch_core_sqldb.c:1538
#5  0x77ec5f19 in dummy_worker (opaque=0x770b9ee0) at threadproc/unix/thread.c:151
#6  0x77fc5014 in start (p=0x76c98d54) at src/thread/pthread_create.c:203
#7  0x77f5523c in __clone () at src/thread/mips/clone.s:33
Backtrace stopped: frame did not save the PC
(gdb)

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Érico Nogueira]

On Thu Oct 28, 2021 at 6:34 PM -03, Sebastian Kemper wrote:
> Am Thu, Oct 28, 2021 at 10:21:39PM +0200 schrieb Sebastian Kemper:
> >
> > I hope the "optimized out" items aren't too much of an issue. Would be
> > great if you could take a look.
>
> Recompiled with "-O0", now it looks better:
>
> 0x77f55320 in _dlstart () from
> /home/sk/tmp/openwrt/scripts/../staging_dir/target-mips_24kc_musl/root-ath79/lib/ld-musl-mips-sf.so.1
> (gdb) c
> Continuing.
> warning: Could not load shared library symbols for
> /usr/lib/libwolfssl.so.4.8.1.d8795272.
> Do you need "set solib-search-path" or "set sysroot"?
> process 12781 is executing new program: /usr/bin/freeswitch
> warning: Could not load shared library symbols for
> /usr/lib/libwolfssl.so.4.8.1.d8795272.
> Do you need "set solib-search-path" or "set sysroot"?
> [New Thread 12781.12810]
> [New Thread 12781.12782]
> [New Thread 12781.12783]
> [New Thread 12781.12785]
> [New Thread 12781.12796]
> [New Thread 12781.12809]
>
> Thread 2 "freeswitch" received signal SIGSEGV, Segmentation fault.
> [Switching to Thread 12781.12810]
> 0x77d7093f in vxprintf (func=0x77d70c71 <mout>, arg=0x76c98a70,
> useExtended=0, fmt=0x77ee2b8e "q'", ap=0x76c98c4c) at
> src/switch_mprintf.c:689
> 689 for (i = n = 0; (ch = escarg[i]) != 0; i++) {
> (gdb) bt
> #0 0x77d7093f in vxprintf (func=0x77d70c71 <mout>, arg=0x76c98a70,
> useExtended=0, fmt=0x77ee2b8e "q'", ap=0x76c98c4c) at
> src/switch_mprintf.c:689
> #1 0x77d70df7 in base_vprintf (xRealloc=0x77d70e6d <printf_realloc>,
> useInternal=0,
> zInitBuf=0x76c98acc "delete from registrations where expires > 0 and
> expires <= 2012362356 and hostname='", nInitBuf=350,
> zFormat=0x77ee2b40 "delete from registrations where expires > 0 and
> expires <= %ld and hostname='%q'", ap=0x76c98c44) at
> src/switch_mprintf.c:860
> #2 0x77d70f81 in switch_mprintf (zFormat=0x77ee2b40 "delete from
> registrations where expires > 0 and expires <= %ld and hostname='%q'")
> at src/switch_mprintf.c:903
> #3 0x77d8d395 in switch_core_expire_registration (force=0) at
> src/switch_core_sqldb.c:3554

Line 3554 is:

		sql = switch_mprintf("delete from registrations where expires > 0 and expires <= %ld and hostname='%q'", now, switch_core_get_switchname());

It's using '%ld' for 'now', which is time_t. Will add a commit to fix it
in my PR. Replace with '%lld' if you want to do a quick fix to see if
you catch any other errors.

> #4 0x77d85975 in switch_core_sql_db_thread (thread=0x770b9ee0, obj=0x0)
> at src/switch_core_sqldb.c:1538
> #5 0x77ec5f19 in dummy_worker (opaque=0x770b9ee0) at
> threadproc/unix/thread.c:151
> #6 0x77fc5014 in start (p=0x76c98d54) at src/thread/pthread_create.c:203
> #7 0x77f5523c in __clone () at src/thread/mips/clone.s:33
> Backtrace stopped: frame did not save the PC
> (gdb)

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Sebastian Kemper]

Am Fri, Oct 29, 2021 at 12:10:05AM -0300 schrieb Érico Nogueira:
>
> Line 3554 is:
>
> 		sql = switch_mprintf("delete from registrations where expires > 0 and expires <= %ld and hostname='%q'", now, switch_core_get_switchname());
>
> It's using '%ld' for 'now', which is time_t. Will add a commit to fix it
> in my PR. Replace with '%lld' if you want to do a quick fix to see if
> you catch any other errors.
>

Thanks! The segfault now doesn't happen anymore.

Now freeswitch seems to loop around (unusable). The log is plastered
with these messages:

1970-01-01 00:36:58.-797115 23.33% [CRIT] switch_time.c:1203 Virtual Migration Detected! Syncing Clock
1970-01-01 00:36:58.-797115 23.33% [INFO] switch_time.c:626 Clock synchronized to system time.
1970-01-01 00:36:58.-797115 23.33% [CRIT] switch_time.c:1203 Virtual Migration Detected! Syncing Clock
1970-01-01 00:36:58.-797115 23.33% [INFO] switch_time.c:626 Clock synchronized to system time.

I have a hunch that that is an issue with libapr, which freeswitch has
bundled. Incidentally, a few days ago I was playing around with mod php
and apache (which I'm sure you know uses apr). I put up a small php
website which shows the date and time. And whenever I hit F5 in the
browser it would give me a different wrong time and date, but always
around 1970.

I found that apr bundles a test suite. This also includes a test called
"testtime". It finds that the apr time is way different compared to OS
time. Code snippet:

static void test_now(abts_case *tc, void *data)
{
    apr_time_t timediff;
    apr_time_t current;
    time_t os_now;

    current = apr_time_now();
    time(&os_now);

    timediff = os_now - (current / APR_USEC_PER_SEC);
    /* Even though these are called so close together, there is the chance
     * that the time will be slightly off, so accept anything between -1 and
     * 1 second.
     */
    ABTS_ASSERT(tc, "apr_time and OS time do not agree",
             (timediff > -2) && (timediff < 2));
}

This happens when I run it (the other two "Line" warnings are from
different tests!):

testtime            : |Line 69: apr_time and OS time do not agree
|Line 110: Mismatch in tm_sec
|Line 204: expected <Thu Jan  1 01:00:00 1970>, but saw <Sat Sep 14 21:05:36 2002>
FAILED 3 of 13
Failed Tests   		Total	Fail	Failed %
===================================================
testtime       		   13	   3	 23.08%

(gdb) b test/testtime.c:57
Breakpoint 1 at 0x405837: file testtime.c, line 61.
(gdb) c
Continuing.

Breakpoint 1, test_now (tc=0x7fffacd0, data=0x0) at testtime.c:61
61	    current = apr_time_now();
(gdb) bt
#0  test_now (tc=0x7fffacd0, data=0x0) at testtime.c:61
#1  0x00404b43 in abts_run_test (ts=0x77f0bde0, f=0x40581d <test_now>, value=0x0) at abts.c:171
#2  0x00406733 in testtime (suite=0x77f0bde0) at testtime.c:300
#3  0x004055d9 in main (argc=3, argv=0x7fffadb4) at abts.c:429
(gdb) p current
$1 = 193277741781
(gdb) p &current
$2 = (apr_time_t *) 0x7fffac90
(gdb) p os_now
$3 = 19521141760827868
(gdb) p &os_now
$4 = (time_t *) 0x7fffac88
(gdb) p timediff
$5 = 19521141756395521
(gdb) p &timediff
$6 = (apr_time_t *) 0x7fffac98
(gdb) p time
$7 = {time32_t (time32_t *)} 0x77fd0b08 <time>
(gdb) p &time
$8 = (time32_t (*)(time32_t *)) 0x77fd0b08 <time>
(gdb) c
Continuing.
[Inferior 1 (process 14739) exited with code 01]
(gdb)

To me it looks like apr is also using a 64 bit type for time. So it's a
bit of a surprise for me that there is a problem. I find it also strange
that the time function (which seems to be from libc) seems to be related
to a 32 bit type.

Can you maybe make sense of this?

Kind regards,
Seb

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Szabolcs Nagy]

* Sebastian Kemper <sebastian_ml@gmx.net> [2021-10-29 16:40:02 +0200]:
> static void test_now(abts_case *tc, void *data)
> {
>     apr_time_t timediff;
>     apr_time_t current;
>     time_t os_now;
> 
>     current = apr_time_now();
>     time(&os_now);
> 
>     timediff = os_now - (current / APR_USEC_PER_SEC);
>     /* Even though these are called so close together, there is the chance
>      * that the time will be slightly off, so accept anything between -1 and
>      * 1 second.
>      */
>     ABTS_ASSERT(tc, "apr_time and OS time do not agree",
>              (timediff > -2) && (timediff < 2));
> }
> 
> This happens when I run it (the other two "Line" warnings are from
> different tests!):
> 
> testtime            : |Line 69: apr_time and OS time do not agree
> |Line 110: Mismatch in tm_sec
> |Line 204: expected <Thu Jan  1 01:00:00 1970>, but saw <Sat Sep 14 21:05:36 2002>
> FAILED 3 of 13
> Failed Tests   		Total	Fail	Failed %
> ===================================================
> testtime       		   13	   3	 23.08%
> 
> (gdb) b test/testtime.c:57
> Breakpoint 1 at 0x405837: file testtime.c, line 61.
> (gdb) c
> Continuing.
> 
> Breakpoint 1, test_now (tc=0x7fffacd0, data=0x0) at testtime.c:61
> 61	    current = apr_time_now();
> (gdb) bt
> #0  test_now (tc=0x7fffacd0, data=0x0) at testtime.c:61
> #1  0x00404b43 in abts_run_test (ts=0x77f0bde0, f=0x40581d <test_now>, value=0x0) at abts.c:171
> #2  0x00406733 in testtime (suite=0x77f0bde0) at testtime.c:300
> #3  0x004055d9 in main (argc=3, argv=0x7fffadb4) at abts.c:429
> (gdb) p current
> $1 = 193277741781
> (gdb) p &current
> $2 = (apr_time_t *) 0x7fffac90
> (gdb) p os_now
> $3 = 19521141760827868
> (gdb) p &os_now
> $4 = (time_t *) 0x7fffac88
> (gdb) p timediff
> $5 = 19521141756395521

these values are completely wrong (may be not set up yet,
you cannot rely on line numbers in optimized code)

time on your system now should be around

1635500000

current / 1000000 is

193277

which is 1970-01-03 05:41:17

os_now is far in the future.


> (gdb) p &timediff
> $6 = (apr_time_t *) 0x7fffac98
> (gdb) p time
> $7 = {time32_t (time32_t *)} 0x77fd0b08 <time>
> (gdb) p &time
> $8 = (time32_t (*)(time32_t *)) 0x77fd0b08 <time>
> (gdb) c
> Continuing.
> [Inferior 1 (process 14739) exited with code 01]
> (gdb)
> 
> To me it looks like apr is also using a 64 bit type for time. So it's a
> bit of a surprise for me that there is a problem. I find it also strange
> that the time function (which seems to be from libc) seems to be related
> to a 32 bit type.
> 
> Can you maybe make sense of this?

you need to debug this further, all sorts of things may be wrong here.

i'd remove all other tests from the test exe and break on gettimeofday
and time and see what the libc returns, also print the time in the test.

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Sebastian Kemper]

Am Fri, Oct 29, 2021 at 11:04:45PM +0200 schrieb Szabolcs Nagy:
> * Sebastian Kemper <sebastian_ml@gmx.net> [2021-10-29 16:40:02 +0200]:
> > (gdb) p current
> > $1 = 193277741781
> > (gdb) p &current
> > $2 = (apr_time_t *) 0x7fffac90
> > (gdb) p os_now
> > $3 = 19521141760827868
> > (gdb) p &os_now
> > $4 = (time_t *) 0x7fffac88
> > (gdb) p timediff
> > $5 = 19521141756395521
>
> these values are completely wrong (may be not set up yet,
> you cannot rely on line numbers in optimized code)
>
> time on your system now should be around
>
> 1635500000
>
> current / 1000000 is
>
> 193277
>
> which is 1970-01-03 05:41:17
>
> os_now is far in the future.
>

Hello Szabolcs,

I changed the test program a little bit:

--- a/test/testtime.c
+++ b/test/testtime.c
@@ -21,6 +21,7 @@
 #include "testutil.h"
 #include "apr_strings.h"
 #include <time.h>
+#include <stdio.h>

 #define STR_SIZE 45

@@ -57,6 +58,7 @@ static void test_now(abts_case *tc, void
     apr_time_t timediff;
     apr_time_t current;
     time_t os_now;
+    struct tm * timeinfo;

     current = apr_time_now();
     time(&os_now);
@@ -66,6 +68,10 @@ static void test_now(abts_case *tc, void
      * that the time will be slightly off, so accept anything between -1 and
      * 1 second.
      */
+    timeinfo = localtime ( &os_now );
+    printf ( "Current local time and date: %s - %lld seconds since epoch\n", asctime (timeinfo), os_now);
+    timeinfo = localtime ( &current );
+    printf ( "Current APR time and date: %s - %lld seconds since epoch\n", asctime (timeinfo), current);
     ABTS_ASSERT(tc, "apr_time and OS time do not agree",
              (timediff > -2) && (timediff < 2));
 }

The output is:

Current local time and date: Sat Oct 30 00:25:11 2021 - 7024617916842658549 seconds since epoch
Current APR time and date: Mon Jan  5 10:46:45 1970 - 1635546302107561 seconds since epoch
|Line 76: apr_time and OS time do not agree

(gdb) b time
Breakpoint 1 at 0x77fd0b08: file compat/time32/time32.c, line 7.
(gdb) b gettimeofday
Breakpoint 2 at 0x77fcff6c: file compat/time32/gettimeofday_time32.c, line 7.
(gdb) b apr_time_now
Function "apr_time_now" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 3 (apr_time_now) pending.
(gdb) c
Continuing.

Breakpoint 1, time (p=0x7fffac90) at compat/time32/time32.c:7
7	{
(gdb) next
8		time_t t = time(0);
(gdb)
9		if (t < INT32_MIN || t > INT32_MAX) {
(gdb)
13		if (p) *p = t;
(gdb)
14		return t;
(gdb)
test_now (tc=0x7fffacd0, data=0x0) at testtime.c:66
66	    timediff = os_now - (current / APR_USEC_PER_SEC);
(gdb) p os_now
$1 = 7024617916842658549
(gdb) p current
$2 = 1635546302107561
(gdb) p APR_USEC_PER_SEC
$3 = 1000000
(gdb) c
Continuing.
[Inferior 1 (process 15506) exited with code 01]

So OS time is correct. Something not working right with apr.

> > (gdb) p &timediff
> > $6 = (apr_time_t *) 0x7fffac98
> > (gdb) p time
> > $7 = {time32_t (time32_t *)} 0x77fd0b08 <time>
> > (gdb) p &time
> > $8 = (time32_t (*)(time32_t *)) 0x77fd0b08 <time>
> > (gdb) c
> > Continuing.
> > [Inferior 1 (process 14739) exited with code 01]
> > (gdb)
> >
> > To me it looks like apr is also using a 64 bit type for time. So it's a
> > bit of a surprise for me that there is a problem. I find it also strange
> > that the time function (which seems to be from libc) seems to be related
> > to a 32 bit type.
> >
> > Can you maybe make sense of this?
>
> you need to debug this further, all sorts of things may be wrong here.
>
> i'd remove all other tests from the test exe and break on gettimeofday
> and time and see what the libc returns, also print the time in the test.

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Rich Felker]

On Sat, Oct 30, 2021 at 12:44:05AM +0200, Sebastian Kemper wrote:
> Am Fri, Oct 29, 2021 at 11:04:45PM +0200 schrieb Szabolcs Nagy:
> > * Sebastian Kemper <sebastian_ml@gmx.net> [2021-10-29 16:40:02 +0200]:
> > > (gdb) p current
> > > $1 = 193277741781
> > > (gdb) p &current
> > > $2 = (apr_time_t *) 0x7fffac90
> > > (gdb) p os_now
> > > $3 = 19521141760827868
> > > (gdb) p &os_now
> > > $4 = (time_t *) 0x7fffac88
> > > (gdb) p timediff
> > > $5 = 19521141756395521
> >
> > these values are completely wrong (may be not set up yet,
> > you cannot rely on line numbers in optimized code)
> >
> > time on your system now should be around
> >
> > 1635500000
> >
> > current / 1000000 is
> >
> > 193277
> >
> > which is 1970-01-03 05:41:17
> >
> > os_now is far in the future.
> >
> 
> Hello Szabolcs,
> 
> I changed the test program a little bit:
> 
> --- a/test/testtime.c
> +++ b/test/testtime.c
> @@ -21,6 +21,7 @@
>  #include "testutil.h"
>  #include "apr_strings.h"
>  #include <time.h>
> +#include <stdio.h>
> 
>  #define STR_SIZE 45
> 
> @@ -57,6 +58,7 @@ static void test_now(abts_case *tc, void
>      apr_time_t timediff;
>      apr_time_t current;
>      time_t os_now;
> +    struct tm * timeinfo;
> 
>      current = apr_time_now();
>      time(&os_now);
> @@ -66,6 +68,10 @@ static void test_now(abts_case *tc, void
>       * that the time will be slightly off, so accept anything between -1 and
>       * 1 second.
>       */
> +    timeinfo = localtime ( &os_now );
> +    printf ( "Current local time and date: %s - %lld seconds since epoch\n", asctime (timeinfo), os_now);
> +    timeinfo = localtime ( &current );
> +    printf ( "Current APR time and date: %s - %lld seconds since epoch\n", asctime (timeinfo), current);
>      ABTS_ASSERT(tc, "apr_time and OS time do not agree",
>               (timediff > -2) && (timediff < 2));
>  }
> 
> The output is:
> 
> Current local time and date: Sat Oct 30 00:25:11 2021 - 7024617916842658549 seconds since epoch
> Current APR time and date: Mon Jan  5 10:46:45 1970 - 1635546302107561 seconds since epoch
> |Line 76: apr_time and OS time do not agree
> 
> (gdb) b time
> Breakpoint 1 at 0x77fd0b08: file compat/time32/time32.c, line 7.
> (gdb) b gettimeofday
> Breakpoint 2 at 0x77fcff6c: file compat/time32/gettimeofday_time32.c, line 7.
> (gdb) b apr_time_now
> Function "apr_time_now" not defined.
> Make breakpoint pending on future shared library load? (y or [n]) y
> Breakpoint 3 (apr_time_now) pending.
> (gdb) c
> Continuing.
> 
> Breakpoint 1, time (p=0x7fffac90) at compat/time32/time32.c:7
> 7	{
> (gdb) next
> 8		time_t t = time(0);
> (gdb)
> 9		if (t < INT32_MIN || t > INT32_MAX) {
> (gdb)
> 13		if (p) *p = t;
> (gdb)
> 14		return t;
> (gdb)
> test_now (tc=0x7fffacd0, data=0x0) at testtime.c:66
> 66	    timediff = os_now - (current / APR_USEC_PER_SEC);
> (gdb) p os_now
> $1 = 7024617916842658549
> (gdb) p current
> $2 = 1635546302107561
> (gdb) p APR_USEC_PER_SEC
> $3 = 1000000
> (gdb) c
> Continuing.
> [Inferior 1 (process 15506) exited with code 01]

This function should not be being called. It's only for ABI-compat
with old time32 binaries.

> So OS time is correct. Something not working right with apr.

Likely it is doing something bad bypassing the system headers and
declaring gettimeofday (wrongly) itself...

Rich

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Sebastian Kemper]

Am Fri, Oct 29, 2021 at 09:00:43PM -0400 schrieb Rich Felker:
> On Sat, Oct 30, 2021 at 12:44:05AM +0200, Sebastian Kemper wrote:
> > Breakpoint 3 (apr_time_now) pending.
> > (gdb) c
> > Continuing.
> >
> > Breakpoint 1, time (p=0x7fffac90) at compat/time32/time32.c:7
> > 7	{
> > (gdb) next
> > 8		time_t t = time(0);
> > (gdb)
> > 9		if (t < INT32_MIN || t > INT32_MAX) {
> > (gdb)
> > 13		if (p) *p = t;
> > (gdb)
> > 14		return t;
> > (gdb)
> > test_now (tc=0x7fffacd0, data=0x0) at testtime.c:66
> > 66	    timediff = os_now - (current / APR_USEC_PER_SEC);
> > (gdb) p os_now
> > $1 = 7024617916842658549
> > (gdb) p current
> > $2 = 1635546302107561
> > (gdb) p APR_USEC_PER_SEC
> > $3 = 1000000
> > (gdb) c
> > Continuing.
> > [Inferior 1 (process 15506) exited with code 01]
>
> This function should not be being called. It's only for ABI-compat
> with old time32 binaries.

OK. I made a fresh clone from OpenWrt and build from scratch. Now when I
run the test program it segfault when trying to get APR time. I'll
follow up with that later today.

Maybe I had some old libtool cruft lying around, I don't know.

>
> > So OS time is correct. Something not working right with apr.
>
> Likely it is doing something bad bypassing the system headers and
> declaring gettimeofday (wrongly) itself...

I looked at APR source but it doesn't seem to redefine gettimeofday. It
only uses it here:

APR_DECLARE(apr_time_t) apr_time_now(void)
{
    struct timeval tv;
    gettimeofday(&tv, NULL);
    return tv.tv_sec * APR_USEC_PER_SEC + tv.tv_usec;
}

Will let you all know how it goes :) Thanks again!

>
> Rich

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Rich Felker]

On Sat, Oct 30, 2021 at 12:57:05PM +0200, Sebastian Kemper wrote:
> Am Fri, Oct 29, 2021 at 09:00:43PM -0400 schrieb Rich Felker:
> > On Sat, Oct 30, 2021 at 12:44:05AM +0200, Sebastian Kemper wrote:
> > > So OS time is correct. Something not working right with apr.
> >
> > Likely it is doing something bad bypassing the system headers and
> > declaring gettimeofday (wrongly) itself...
> 
> I looked at APR source but it doesn't seem to redefine gettimeofday. It
> only uses it here:

I said declare, not define, as in omitting sys/time.h and making its
own declaration (or calling it without one). However AFAICT that
doesn't seem to be the case, unless APR_HAVE_SYS_TIME_H is
misdetected. You might check the disassembly of this file and see
what's actually getting called.

Rich

Re: [musl] Re: freeswitch and musl 1.2.x (time64 most likely)

[Sebastian Kemper]

Am Sat, Oct 30, 2021 at 01:56:26PM -0400 schrieb Rich Felker:
> On Sat, Oct 30, 2021 at 12:57:05PM +0200, Sebastian Kemper wrote:
> > Am Fri, Oct 29, 2021 at 09:00:43PM -0400 schrieb Rich Felker:
> > > On Sat, Oct 30, 2021 at 12:44:05AM +0200, Sebastian Kemper wrote:
> > > > So OS time is correct. Something not working right with apr.
> > >
> > > Likely it is doing something bad bypassing the system headers and
> > > declaring gettimeofday (wrongly) itself...
> >
> > I looked at APR source but it doesn't seem to redefine gettimeofday. It
> > only uses it here:
>
> I said declare, not define, as in omitting sys/time.h and making its
> own declaration (or calling it without one). However AFAICT that
> doesn't seem to be the case, unless APR_HAVE_SYS_TIME_H is
> misdetected. You might check the disassembly of this file and see
> what's actually getting called.
>

Hello Rich, all,

Sorry for getting sidetracked with apr. That was my mistake. I must've
had old cruft around my builroot. Starting the buildroot from scratch
resolved all if it. apr runs fine.

Érico, thank you for your support! And thanks for the pull request to
freeswitch!

I'll go ahead an push the updated freeswitch to OpenWrt master next.

Kind regards,
Seb

> Rich