| | <<<Back 1 day (to 2020/06/25) | Fwd 1 day (to 2020/06/27)>>> | 20200626 |
| avih | ator: i just had a weird issue for the first time. error: Object is not callable on line 441 here https://github.com/mpv-player/mpv/blob/master/player/javascript/defaults.js#L441 i think it refers to the `timers' array because i don't see what else it could refer to. if you follow this function, you'll see that `timers' starts as an array and stays that way till line 441. the script which uses this has been running for many hours and invoked every few | 11:13.09 |
| | milliseconds. any idea? | 11:13.09 |
| | maybe some integer value wraps or some other similar issue? | 11:13.58 |
| | actually, i'm not sure what "object is not callable" means... | 11:15.06 |
| | obviously i can't reproduce it. | 11:15.51 |
| | the call stack is quite short: process_timers (defaults.js:441) <from> mp_event_loop (defaults.js:743) <from> run_script (native) | 11:17.11 |
| | and the full error is "TypeError: object is not callable" | 11:18.11 |
| ator | the error means you're trying to call a value that's not a function | 11:20.29 |
| | most often if you try to call something like foo.bar() | 11:20.45 |
| | and bar is undefined | 11:20.47 |
| avih | can it refer to anything other than timers.forEach? | 11:20.53 |
| | assuming it got the line right... | 11:21.00 |
| ator | so if you have the line right, I'd double check the type of 'timers.forEach' | 11:21.17 |
| avih | i can't. the script died | 11:21.32 |
| ator | is it really a function? | 11:21.33 |
| avih | on uncaught exceptions i print the trace and the script thread exits | 11:21.48 |
| ator | print(typeof timers.forEach) on the line before | 11:21.51 |
| avih | well, this code has not been modified for years, and it's the first time it errors. try to follow the process_timers function where it's reported. timers is set to [] and nothing changes its type | 11:22.52 |
| ator | oh right, can't reproduce :/ | 11:22.54 |
| | are you calling any C functions? maybe something is messing up the stack | 11:23.23 |
| avih | so it's like the forEach method dissappeared from timers | 11:23.25 |
| ator | maybe something replaced 'timers' with an object that doesn't have Array in its prototype chain? | 11:24.11 |
| avih | at process_timers? probably only one to get the current timestamp as a double in ms since the application (mpv) started at the now() function | 11:24.19 |
| malc_ | ator: just to be certain, seen my privmsg? | 11:24.20 |
| ator | or something messed up the Array.prototype object and deleted forEach from it | 11:24.27 |
| avih | nothing in all my code touches the array prototype | 11:24.57 |
| | ator: i suspect/near-certain it's a mujs issue, if it wasn't clear. | 11:25.22 |
| ator | ah, it says "*object* is not callable" | 11:25.36 |
| avih | yes | 11:25.42 |
| ator | that means the timers.forEach is an object, just not a function | 11:25.44 |
| avih | hmm.. should it be an object? | 11:25.57 |
| ator | we used to print "value is not callable" without saying what the type of the value is | 11:26.03 |
| | functions are objects | 11:26.10 |
| avih | wait, how new is this change from value to function/object? | 11:26.26 |
| ator | with an internal class 'Function' | 11:26.30 |
| | from march 18, 2019 | 11:27.08 |
| | "Issue 95: Improve error message when trying to call a non-callable." | 11:27.15 |
| avih | ok, so not new | 11:27.16 |
| | this is so weird. this code was literally unmodified for years (it's setTimeout/setInterval implementation), and used by many scripts. the script which uses it where it happend now is also used for a long time. | 11:29.12 |
| ator | blame some cosmic ray for flipping a bit! | 11:29.41 |
| avih | so it looks like something got corrupted somewhere | 11:29.48 |
| | fwiw, it has been running for 83155 seconds which is just more than 23 hours | 11:31.42 |
| | ator: are there some integer counters in mujs which could reach the capacity if used enough? | 11:32.28 |
| malc_ | avih: http://www.bash.org/?2999 | 11:35.28 |
| avih | malc_: sorry, i don't follow | 11:36.00 |
| malc_ | avih: sorry, your seconds hours comment just reminded me of this bash quote | 11:36.46 |
| avih | right | 11:37.00 |
| | fwiw, this is on a 50ms setInterval timer. so that value of seconds multiplied by 20 to count the number of times this function was invoking the timer callback | 11:38.43 |
| | (could be a red herring, the function is probably called even more times, but only calls back this number of times) | 11:39.46 |
| | ator: interestingly, when i change the interval from 50 (ms) to 0 (i.e. as fast as possible) it ends up calling back about 50000 times/sec, and another such weird error happened. still not reproducible, but a similar thing happened at least once more for now. | 12:01.29 |
| ator | avih: possibly the garbage collection iterator counter, but if that overflows nothing bad should happen | 12:03.48 |
| avih | can't reproduce still. when it happened the second time, the script was running for few seconds (iirc less than 10). but in followup attempts it has not happened again | 12:04.05 |
| ator | avih: if you can trigger it once, try to do a try/catch around it and print the offending forEach value | 12:04.12 |
| avih | ator: it now happened someplace else. i didn't write down the line because i thought it became reproducible, alas, it has not | 12:04.40 |
| malc_ | road to madness usually begins with "i thought" | 12:05.14 |
| | ends with Lasciate ogni speranza, voi ch'entrate | 12:05.55 |
| | usually | 12:05.57 |
| avih | but anyway, it was that that script which iterated 50k/sec on this function, but the error was different, at a different function, and i don't recall where | 12:06.24 |
| | that same* | 12:06.34 |
| | malc_: i asked the maintainer of 0x0 about the tor issue. i'll let you know once/if i know more | 12:11.42 |
| malc_ | avih: תודה! | 12:13.16 |
| avih | :) | 12:13.24 |
| | malc_: <mia\> the firewall blocks tor exit nodes | 12:13.49 |
| | <avih> is it explained someplace? | 12:13.49 |
| | <mia\> hm nope | 12:13.49 |
| | <mia\> maybe i should add a note | 12:13.49 |
| malc_ | thought so... | 12:14.43 |
| | pastebin is even worse it just relies on cloudflare | 12:14.59 |
| | which is basically no go for tor | 12:15.07 |
| | erm | 12:15.11 |
| | for TOR :) | 12:15.25 |
| ator | for meeee? | 12:15.42 |
| malc_ | i should probably see if there is a onion emoticon in the latest unicode code charts | 12:16.47 |
| | or drop this on the channels with scandinavians | 12:17.11 |
| avih | i so hate intermediate issues. | 12:19.26 |
| | especially those which don't happen frequently | 12:19.36 |
| | ator: if that gc counter uses signed int, maybe you can deterministically zero it at some stage? i signed wraparound is UB, is it not? | 12:20.24 |
| | or use unsigned? | 12:20.33 |
| ator | avih: my bad. gccounter does not wrap around (it's reset each gc cycle) | 12:23.56 |
| | and the gcmark just toggles between 3 values | 12:24.03 |
| | s/3/2 | 12:24.13 |
| avih | right, so not that. | 12:24.14 |
| | the fact that such unexpected exceptions happened twice inside 10 minutes or so is not insignificant IMO. especially that i never got that before. but i still couldn't make it happen a third time... | 12:25.27 |
| ator | avih: I agree it's worrying. | 12:25.54 |
| avih | ator: anything at the commits past 1.0.7 which you think might be somehow related? | 12:26.46 |
| | faulty ram could always be an issue, but i haven't seen signed of it otherwise | 12:27.52 |
| | signs* | 12:28.00 |
| | and it's a relatively new system (6 months or so) | 12:28.54 |
| | cosmic rays shower could be another explanation, though probably unlikely... | 12:30.35 |
| ator | avih: gremlins! | 12:33.33 |
| avih | omg, i did not consider that! | 12:33.47 |
| ator | I don't see any commits post 1.0.7 that ought to be able to affect it | 12:34.00 |
| avih | hmm.. that's worrying to me... | 12:34.13 |
| ator | the only things that have changed since 1.0.7 is removing recursion from the GC and the UTF-8 changes | 12:34.50 |
| avih | i know. but we've already seen two bugs from it, one of them indeterministic. | 12:35.16 |
| ator | if the GC changes were faulty, we'd se a lot more fallout | 12:35.19 |
| avih | though this one is more likely to be a gc issue, if at all, imo. like some objects were not tracked correctly | 12:36.22 |
| | but it's just guesses, and unfortunately i cannot make it happen even in some frequency | 12:37.09 |
| ator | do you have/use exceptions in the normal flow of things? | 12:37.44 |
| | if not you could try running it in gdb and setting a breakpoint at js_throw | 12:38.06 |
| avih | not with default.js, but i'll check if the script where it happened (twice) does. sec. | 12:38.26 |
| | no, it doesn't use try/catch | 12:38.44 |
| ator | and call js_trap(J,0) in the debugger to get a much more detailed stack trace (with stack values, etc) | 12:38.55 |
| | before it hits the longjmp and bails out of there | 12:39.12 |
| avih | the general use of mujs in mpv is like so: mpv loads defaults.js (to provide glue to mpv, and some functions like setInterval, require, etc), and then loads a user script. each defaults+user is independent in its own thread and isolated mujs context. | 12:39.50 |
| | ator: so i should call js_trap(J,0) where i otherwise print the stack trace? | 12:41.11 |
| ator | no, at that point the data is long gone | 12:41.43 |
| | you need to call it before js_throw does the longjmp | 12:41.48 |
| | if you just want a quick hack, put js_trap(J,0) at the top of js_throw() | 12:42.12 |
| | and it'll print a full debugger trace everytime an exception is raised | 12:42.27 |
| avih | interesting. i can do that. | 12:42.42 |
| ator | or just jsR_dumpstack if you want a little bit less detail (js_trap prints the bytecode of the functions as well) | 12:43.35 |
| avih | ator: you mean at jsrun.c:1263 ? | 12:43.43 |
| ator | yes. | 12:43.56 |
| avih | so it will dump the data even if it's caught? | 12:44.27 |
| ator | that will dump the data for all exceptions that are thrown, no matter where and how or what happens to them later | 12:44.47 |
| | every single exception that gets thrown goes through that function to do the actual throwing | 12:45.14 |
| avih | right. should still be fairly minimal. i might use intentional try/catch to test things in some scripts, but it's at most one-off, not recurring | 12:45.27 |
| | ator: like so? https://0x0.st/iJKV.txt | 12:47.15 |
| ator | y | 12:47.25 |
| avih | not inside the if? | 12:47.31 |
| ator | doesn't matter | 12:47.37 |
| avih | k | 12:47.48 |
| ator | the if is just whether there's an actual try/catch environment, or if it should call the PANIC!!! function | 12:48.01 |
| avih | jsrun.c:1285:13: warning: conflicting types for 'jsR_dumpstack' | 12:49.16 |
| | static void jsR_dumpstack(js_State *J) | 12:49.16 |
| | ^ | 12:49.16 |
| | jsrun.c:1285:13: error: static declaration of 'jsR_dumpstack' follows non-static declaration | 12:49.16 |
| | jsrun.c:1265:2: note: previous implicit declaration of 'jsR_dumpstack' was here | 12:49.16 |
| | jsR_dumpstack(J); | 12:49.16 |
| | ^ | 12:49.18 |
| | ok, i added declaration. | 12:50.32 |
| | hmm, i get tons of printouts initially, but i guess i can ignore them for now. | 12:52.01 |
| | ator: what can i add before dumpstack to somehow identify its origin? (filename, line, etc)? | 12:53.28 |
| | i don't quite get what it does, it prints tons of source code. how is this supposed to be stack info? | 12:54.53 |
| ator | avih: run mujs command line script | 13:15.11 |
| | type 'debugger' | 13:15.13 |
| | the 'debugger' statement calls js_trap (which calls jsR_dumpstack) | 13:15.38 |
| | you should be seeing stuff like: | 13:15.50 |
| | stack { | 13:15.58 |
| | 0: [Global] | 13:15.58 |
| | 1: [Script [string]] | 13:15.58 |
| | > 2: undefined | 13:15.58 |
| | 3: undefined | 13:15.58 |
| | } | 13:15.59 |
| | that is the JS stack, the > shows the start of the stack frame for the currently executing function | 13:16.23 |
| | that right there should be enough to pinpoint what/why timers.forEach is going wrong | 13:16.55 |
| avih | ator: i already said, the second time it happened was at a different function. not at timers.forEach. | 13:28.22 |
| | by "it" i mean unexpected exception. | 13:28.41 |
| | and i didn't write it down because i thought it became reproducible. | 13:29.10 |
| ator | avih: that's why I suggested this, so you could get a good stack trace regardless of where it occurs | 13:48.15 |
| avih | yeah. it may be useful. but i have a problem that stderr or wherever it's printed is not really "wired" anywhere unless i execute mpv from a console - which i usually don't. i need some way to capture the output to a file. i might add some hardcoded thing to write it to some file. | 14:14.08 |
| | or maybe use js_report for it. mujs reports can be logged to a file in mpv | 14:16.06 |
| | ator: i don't think it's anything rational. look again at the code of that timers.forEach https://github.com/mpv-player/mpv/blob/master/player/javascript/defaults.js#L441 | 15:18.12 |
| | timers is set to [] initially, and nothing touches it till .forEach is called | 15:18.31 |
| | between it calls back the user's callback of the timer, but timers is hidden from the user's script. it's not accessible by scripts except via the timer functions. | 15:19.08 |
| | so there's nothing at the code which can make timers.forEach not be a function | 15:19.49 |
| | basically, i _really_ don't think it's an actual code issue. it looks more like some corruption someplace, and i don't think a trace would help making sense of it | 15:20.44 |
| ator | avih: a trace could help us see how and what was corrupted | 15:46.26 |
| | btw, I won't be around next week. | 15:47.15 |
| avih | k, enjoy | 15:47.27 |
| | i'll try to hardcode something which appends traces to some file with some info like date etc. maybe i'll be able to capture something. | 15:48.28 |
| malc_ | ator: you should really switch to my build.bash, it's nauseating the way current makefiles mismanage things... (the only thing current build.bash lacks are parallel builds... biggie i know... but current Make/root/file situation is bad) | 16:04.21 |
| | <<<Back 1 day (to 2020/06/25) | Forward 1 day (to 2020/06/27)>>> | |
Log of #mupdf at irc.freenode.net.