Server hangs after upgrade

After doing the schema upgrade, my MusicBrainz server hangs and never returns a response. This happens even when just requesting the root page. Nothing shows in the Catalyst debug. The renderer shows a raven uncaught exception. This happened with an upgraded database and with a clean re-import from dump. This server is a hand built server, not the provided VM.

Any suggestions where to look for the root cause?

Thanks.

Michael

Hey Michael, can you checkout this branch and see if it works for you? Some other people were experiencing similar issues with versions of Node.js < 5.10, and this branch fixes those.

git remote add mwiencek https://github.com/mwiencek/musicbrainz-server.git
git fetch mwiencek
git checkout node-fixes

That’s progress. ./script/resourse_compile.sh took half the time (30 seconds instead of over a minute) and did not through warnings about strings being longer than 256 characters. Catalyst returned something, but it was an error.

[info] *** Request 1 (0.053/s) [17926] [Wed May 17 14:45:35 2017] ***
[debug] Path is "/"
[debug] "GET" request for "/" from "127.0.0.1"
[debug] Created session "a88a3ff41f8089c39fd7f7c383888da34b3f9613"
[debug] Rendering template "main/index.tt"
[warning] GET http://localhost:55901/ caused a warning: Use of uninitialized value $length in numeric lt (<) at lib/MusicBrainz/Server/Renderer.pm line 36.
[debug] The Catalyst::View::TT render() method will start dying on error in a future release. Unless you are calling the render() method manually, you probably want the new behaviour, so set render_die => 1 in config for MusicBrainz::Server::View::Default. If you wish to continue to return the exception rather than throwing it, add render_die => 0 to your config.
[error] Couldn't render template "undef error - malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at lib/MusicBrainz/Server/Renderer.pm line 42.
"
[error] Couldn't render template "undef error - malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at lib/MusicBrainz/Server/Renderer.pm line 42.
"
[debug] Response Code: 500; Content-Type: text/html; charset=utf-8; Content-Length: unknown
[info] Request took 3.376101s (0.296/s)

The renderer also logged errors:

May 17 14:44:59 musicbrainz-test node[17893]: server.js worker started (pid 17899)
May 17 14:45:38 musicbrainz-test node[17893]: TypeError: this is not a typed array.
May 17 14:45:38 musicbrainz-test node[17893]:     at from (native)
May 17 14:45:38 musicbrainz-test node[17893]:     at getResponse (/opt/musicbrainz/musicbrainz-server/root/server/response.js:87:10)
May 17 14:45:38 musicbrainz-test node[17893]:     at Socket.receiveData (/opt/musicbrainz/musicbrainz-server/root/server/createServer.js:78:31)
May 17 14:45:38 musicbrainz-test node[17893]:     at emitOne (events.js:77:13)
May 17 14:45:38 musicbrainz-test node[17893]:     at Socket.emit (events.js:169:7)
May 17 14:45:38 musicbrainz-test node[17893]:     at readableAddChunk (_stream_readable.js:146:16)
May 17 14:45:38 musicbrainz-test node[17893]:     at Socket.Readable.push (_stream_readable.js:110:10)
May 17 14:45:38 musicbrainz-test node[17893]:     at Pipe.onread (net.js:523:20)
May 17 14:45:38 musicbrainz-test node[17893]: worker exited with error code: 1
May 17 14:45:39 musicbrainz-test node[17893]: raven@2.0.0 alert: no DSN provided, error reporting disabled
May 17 14:45:40 musicbrainz-test node[17893]: server.js worker started (pid 17936)
May 17 14:45:45 musicbrainz-test node[17893]: TypeError: this is not a typed array.
May 17 14:45:45 musicbrainz-test node[17893]:     at from (native)
May 17 14:45:45 musicbrainz-test node[17893]:     at getResponse (/opt/musicbrainz/musicbrainz-server/root/server/response.js:87:10)
May 17 14:45:45 musicbrainz-test node[17893]:     at receiveData (/opt/musicbrainz/musicbrainz-server/root/server/createServer.js:78:31)
May 17 14:45:45 musicbrainz-test node[17893]:     at Socket.receiveData (/opt/musicbrainz/musicbrainz-server/root/server/createServer.js:82:9)
May 17 14:45:45 musicbrainz-test node[17893]:     at emitOne (events.js:77:13)
May 17 14:45:45 musicbrainz-test node[17893]:     at Socket.emit (events.js:169:7)
May 17 14:45:45 musicbrainz-test node[17893]:     at readableAddChunk (_stream_readable.js:146:16)
May 17 14:45:45 musicbrainz-test node[17893]:     at Socket.Readable.push (_stream_readable.js:110:10)
May 17 14:45:45 musicbrainz-test node[17893]:     at Pipe.onread (net.js:523:20)
May 17 14:45:45 musicbrainz-test node[17893]: worker exited with error code: 1
May 17 14:45:46 musicbrainz-test node[17893]: raven@2.0.0 alert: no DSN provided, error reporting disabled
May 17 14:45:46 musicbrainz-test node[17893]: server.js worker started (pid 17948)

Interesting, thanks for those logs. What version of Node do you have? node --version

So far I’ve only tested things with Node v0.12 and v7 which is quite a huge jump, so there may be other incompatibilities in between which I have to fix.

Node is v4.2.6 from Ubuntu 16.04.2 LTS.

Let me know if you need anything else.

Michael

I’ve updated the branch I mentioned previously if you want to give that another try. Force-pushed, so you’ll need to do this:

git checkout node-fixes
git fetch mwiencek
git reset --hard mwiencek/node-fixes

No change on the Catalyst side.

Here’s the renderer error.

May 17 15:56:20 musicbrainz-test systemd[1]: Started Musicbrainz Renderer.
May 17 15:56:23 musicbrainz-test node[18577]: raven@2.0.0 alert: no DSN provided, error reporting disabled
May 17 15:56:24 musicbrainz-test node[18577]: server.js listening on /var/run/musicbrainz/renderer.socket (pid 18577)
May 17 15:56:25 musicbrainz-test node[18577]: raven@2.0.0 alert: no DSN provided, error reporting disabled
May 17 15:56:26 musicbrainz-test node[18577]: server.js worker started (pid 18584)
May 17 15:57:05 musicbrainz-test node[18577]: TypeError: expected a string
May 17 15:57:05 musicbrainz-test node[18577]:     at exports.bufferFrom (/opt/musicbrainz/musicbrainz-server/root/server/buffer.js:21:13)
May 17 15:57:05 musicbrainz-test node[18577]:     at getResponse (/opt/musicbrainz/musicbrainz-server/root/server/response.js:78:10)
May 17 15:57:05 musicbrainz-test node[18577]:     at Socket.receiveData (/opt/musicbrainz/musicbrainz-server/root/server/createServer.js:69:31)
May 17 15:57:05 musicbrainz-test node[18577]:     at emitOne (events.js:77:13)
May 17 15:57:05 musicbrainz-test node[18577]:     at Socket.emit (events.js:169:7)
May 17 15:57:05 musicbrainz-test node[18577]:     at readableAddChunk (_stream_readable.js:146:16)
May 17 15:57:05 musicbrainz-test node[18577]:     at Socket.Readable.push (_stream_readable.js:110:10)
May 17 15:57:05 musicbrainz-test node[18577]:     at Pipe.onread (net.js:523:20)
May 17 15:57:05 musicbrainz-test node[18577]: worker exited with error code: 1
May 17 15:57:07 musicbrainz-test node[18577]: raven@2.0.0 alert: no DSN provided, error reporting disabled
May 17 15:57:07 musicbrainz-test node[18577]: server.js worker started (pid 18602)
May 17 15:57:09 musicbrainz-test node[18577]: TypeError: expected a string
May 17 15:57:09 musicbrainz-test node[18577]:     at exports.bufferFrom (/opt/musicbrainz/musicbrainz-server/root/server/buffer.js:21:13)
May 17 15:57:09 musicbrainz-test node[18577]:     at getResponse (/opt/musicbrainz/musicbrainz-server/root/server/response.js:78:10)
May 17 15:57:09 musicbrainz-test node[18577]:     at receiveData (/opt/musicbrainz/musicbrainz-server/root/server/createServer.js:69:31)
May 17 15:57:09 musicbrainz-test node[18577]:     at Socket.receiveData (/opt/musicbrainz/musicbrainz-server/root/server/createServer.js:73:9)
May 17 15:57:09 musicbrainz-test node[18577]:     at emitOne (events.js:77:13)
May 17 15:57:09 musicbrainz-test node[18577]:     at Socket.emit (events.js:169:7)
May 17 15:57:09 musicbrainz-test node[18577]:     at readableAddChunk (_stream_readable.js:146:16)
May 17 15:57:09 musicbrainz-test node[18577]:     at Socket.Readable.push (_stream_readable.js:110:10)
May 17 15:57:09 musicbrainz-test node[18577]:     at Pipe.onread (net.js:523:20)
May 17 15:57:09 musicbrainz-test node[18577]: worker exited with error code: 1
May 17 15:57:10 musicbrainz-test node[18577]: raven@2.0.0 alert: no DSN provided, error reporting disabled
May 17 15:57:11 musicbrainz-test node[18577]: server.js worker started (pid 18616)

I left a typo in the code which I think is causing that. Can you fetch the code and try again?

(Unfortunately the earliest Node v4 I can easily get on a Mac is 4.8, which doesn’t have these problems. Thanks for testing it on your setup.)

Better! No Catalyst or renderer error. But I’m not getting the styling. Did I forget a step or is that still part of this issue?

Michael

Good to hear! You should definitely be getting the styling if you ran ./script/compile_resources.sh, but if not, it sounds like a separate issue. Perhaps try running it again and see if it outputs any errors. It should output the CSS to the directory “root/static/build/styles/” (relative to the git checkout).

If there are no errors and the build directory isn’t empty, you can open your web browser’s developer tools and see which CSS files it’s failing to request. If those files appear under the build directory still, the last thing to check would be that you don’t have any incorrect MB_SERVER_ROOT or STATIC_FILES_DIR settings in lib/DBDefs.pm.

There were no errors on the first go around with ./script/compile_resources.sh. On the second run, it was back to taking over a minute and throwing lots of WARN: Output exceeds 256 characters warnings.

But I mucked up my permissions when I started from scratch trying to troubleshoot.

I’ll do some more testing on the renderer fix and let you know if I find any problems.

Thanks!

Michael

@Bitmap, I haven’t run into any issues in my testing so far. :+1: Any idea when this might merge back to master?

Thanks.

Michael

Has this fix been merged to master? I’m working on setting up a new replica from scratch with Node 7.8.0, Ubuntu 14.04 and am getting the same error. The code was pulled from /master today.

I also tried using Node 4.8.3 and 4.2.6, all running under NVM. Same result in each case.

Thanks!

It looked like it was to me, but maybe @Bitmap can confirm.

If I remember correctly, what I did was I checked out v-2017-05-15-schema-change and then cherry-picked 95469fc based on what I saw in PR 510. That’s been working for me on 4.2.6 without NVM.

Michael

1 Like