Panel: Daemon: Callback was already called

[Sapd]

Short description: The daemon does not start and throws an nonsaying error.

• Version of Daemon: v0.6.11
• Server's OS: CentOS 7 (Kernel 3.10.0-957.5.1.el7.x86_64)
• Docker Version: 18.09.2
• Panel Version: 0.7.12

Diagnostics (Attention: Error only visible on console, see below!): https://hastebin.com/uhiwegudiw

* Description *
After updating the daemon to the latest version, I get this error when I try to start up (e.g. npm start, using root):

Unhandled Rejection at: Promise Promise {
  <rejected> Error: Callback was already called.
    at /srv/daemon/node_modules/async/dist/async.js:966:32
    at /srv/daemon/node_modules/async/dist/async.js:3885:13
    at initContainer.err (/srv/daemon/src/controllers/server.js:91:32)
    at docker.Docker (/srv/daemon/src/controllers/server.js:131:24)
    at process._tickDomainCallback (internal/process/next_tick.js:135:7) }

Before updating, everything worked as expected. I also deactivated SELinux temporarily, to see if this is the issue of the problem (it still made the same error). Docker is up and running of course. As I am not familiar with the code, I'm stuck.

[parkervcp]

What version of nodejs are you using?

[Sapd]

@parkervcp NodeJS v6.16.0

[parkervcp]

Update your node js.

[Sapd]

@parkervcp The docs mentioned to install v8 (however I think it was missing in the update instruction).

So I installed v8.15.1 (checked with node -v. However it gives me exactly the same error as above.

[DaneEveritt]

Can you please provide context around the error, not just the error itself.

[Sapd]

The full logs were provided in the initial post. What do you exactly mean by context?

To describe more precisely:
After the last log entry (see the hastebin log in the initial post):

INFO wings: Configuring websocket for daemon stats...

The error mentioned in the initial post shows and the daemon gets stuck (it doesn't crash - but also nothing happens either). To get the full stack trace, I used the option --trace-warnings, as pterodactyl doesn't catch all rejections.

Also more info: The system is fully updated and I verified that docker still works, by starting an ubuntu container with bash.

Also I tried erasing the whole daemon folder, reinstalling it according to the docs, but the error still remains. Also like I said, before updating, everything worked.

[DaneEveritt]

I mean please provide more context around the error you're reporting from the logs. You're just providing the Unhandled Rejection at: Promise Promise but what happened before that in the output (and after if there is anything).

[Sapd]

Unfortunately, that is actually all that is displayed.
This is simply the full console output copy pasted:
https://gist.github.com/Sapd/4286bbe804ef853c63a9b8118466c272
(Note that the first error line differs, because before I also tried to directly catch the error with a code snippet, the rest is exactly the same.)

Sometimes also INFO wings: Configuring websocket for daemon stats... appears after the last line (not every time, because of async I guess).

[AreYouRlyScared]

I'm going to make a guess that version 6 is still installed on the system and it's using that and not the version 8 you installed.

[Sapd]

I'm going to make a guess that version 6 is still installed on the system and it's using that and not the version 8 you installed.

I was thinking about that, too. The weird thing is, that node -v gives me the correct version. I also directly used node src/index.js | node_modules/bunyan/bin/bunyan -o short giving me the same problem. Additionally I searched for traces of the old version (via yum and in the /usr folders, all confirming the correct version)
However, when I'm at home I will try to delete all traces of Node JS, the rpm repositorys and try to do a complete new install of NodeJS.

[Sapd]

I tried now to remove every trace of NodeJS (remove with yum, clean rum repositorys, check if node is there). Then even tried it with the binary archive - however with the same results as above.

So I now completely trashed the vServer, reinstalled it and it works again. I can only assume that the error was caused by the update. But I guess finding the exact reason takes too much time and is not worth it.

[MrDienns]

I am currently facing the same issue. Can we re-open this?

 09 15:24:46 SP-32-1 systemd[1]: Started Pterodactyl Wings Daemon.
Mar 09 15:24:46 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"+ ------------------------------------ +","time":"2019-03-09T14:24:46.792Z","v":0}
Mar 09 15:24:46 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"| Running Pterodactyl Daemon v0.6.12    |","time":"2019-03-09T14:24:46.793Z","v":0}
Mar 09 15:24:46 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"|        https://pterodactyl.io        |","time":"2019-03-09T14:24:46.793Z","v":0}
Mar 09 15:24:46 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"|  Copyright 2015 - 2019 Dane Everitt  |","time":"2019-03-09T14:24:46.793Z","v":0}
Mar 09 15:24:46 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"+ ------------------------------------ +","time":"2019-03-09T14:24:46.793Z","v":0}
Mar 09 15:24:46 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Loading modules, this could take a few seconds.","time":"2019-03-09T14:24:46.793Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Modules loaded, starting Pterodactyl Daemon...","time":"2019-03-09T14:24:47.008Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Configuring user pterodactyl (id: 998) as the owner of all server files.","time":"2019-03-09T14:24:47.046Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Configuring timezone file location...","time":"2019-03-09T14:24:47.072Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Checking container networking environment...","time":"2019-03-09T14:24:47.073Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Found network interface for daemon: pterodactyl_nw","time":"2019-03-09T14:24:47.077Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Ensuring correct network interface for containers...","time":"2019-03-09T14:24:47.077Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Networking gateway detected as 172.18.0.1 for interface: pterodactyl0.","time":"2019-03-09T14:24:47.081Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Contacting panel to retrieve a list of currrent Eggs available to the node.","time":"2019-03-09T14:24:47.082Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Checking existing eggs against Panel response...","time":"2019-03-09T14:24:47.156Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Beginning server initialization process.","time":"2019-03-09T14:24:47.161Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: (node:18253) UnhandledPromiseRejectionWarning: Error: Callback was already called.
Mar 09 15:24:47 SP-32-1 node[18253]:     at /srv/daemon/node_modules/async/dist/async.js:966:32
Mar 09 15:24:47 SP-32-1 node[18253]:     at /srv/daemon/node_modules/async/dist/async.js:3885:13
Mar 09 15:24:47 SP-32-1 node[18253]:     at initContainer.err (/srv/daemon/src/controllers/server.js:91:32)
Mar 09 15:24:47 SP-32-1 node[18253]:     at docker.Docker (/srv/daemon/src/controllers/server.js:131:24)
Mar 09 15:24:47 SP-32-1 node[18253]:     at <anonymous>
Mar 09 15:24:47 SP-32-1 node[18253]:     at process._tickDomainCallback (internal/process/next_tick.js:229:7)
Mar 09 15:24:47 SP-32-1 node[18253]: (node:18253) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id
Mar 09 15:24:47 SP-32-1 node[18253]: (node:18253) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Configuring websocket for daemon stats...","time":"2019-03-09T14:24:47.495Z","v":0}
Mar 09 15:24:47 SP-32-1 node[18253]: {"name":"wings","hostname":"SP-32-1","pid":18253,"level":30,"msg":"Configuring internal SFTP server...","time":"2019-03-09T14:24:47.495Z","v":0}

The daemon doesn't fully start up and is not accepting connections.

[DaneEveritt]

Please provide your system information, including Nodejs version.

[MrDienns]

OS: Linux SP-32-1 4.13.0-32-generic #35~16.04.1-Ubuntu SMP Thu Jan 25 10:13:43 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
NPM: 6.9.0
Node: v8.15.1
Panel: 0.7.13
Daemon: 0.6.12

[MrDienns]

Note: downgrading to 0.6.10 seems to work as a temporarily workaround. 0.6.11 has the same issue as mentioned by @Sapd. Though this results in some FTP issues in combination with the latest panel...

[icedmoca]

Getting the same issue.. "responseCode": 403,

[OrionDevelopment]

And another one.

[OrionDevelopment]

We ran into this after the disk became full, stopped the service, moved the data, created a symlink, and started the service again
And this popped up.

[DaneEveritt]

@icedmoca that has nothing to do with this issue.

@OrionDevelopment please provide the same logs as everyone else is. Saying "this is happening to me" without logs doesn't help us track it down. :)

[OrionDevelopment]

@DaneEveritt Actually i fixed it.
I added a log call before the violating next(err); call in server.js.

That pushed out a log entry indicating that it had problems resolving symbolic links.
I removed my symbolic link and that fixed it.
Looking at the code and the resulting behaviour.
It seems that when you initialize the container and that fails then your callback is called twice. Once with an informational log and once with the error, causing it to fail.

Hope that helps

[Destreyf]

I just wanted to follow up on this as well, i had the same issue, with a symlink as @OrionDevelopment did.

I have a central file server that i use so i had that mounted as /mnt/minecraft-hosting and was symlinking it to /srv/daemon-data which prevented the nodes from starting the daemon correctly, i remapped my mount to just directly mount to /srv/daemon-data and it worked.

My log file looked like this for reference:

04:24:50.955Z  INFO wings: + ------------------------------------ +
04:24:50.956Z  INFO wings: | Running Pterodactyl Daemon v0.6.12    |
04:24:50.956Z  INFO wings: |        https://pterodactyl.io        |
04:24:50.956Z  INFO wings: |  Copyright 2015 - 2019 Dane Everitt  |
04:24:50.956Z  INFO wings: + ------------------------------------ +
04:24:50.956Z  INFO wings: Loading modules, this could take a few seconds.
04:24:51.299Z  INFO wings: Modules loaded, starting Pterodactyl Daemon...
04:24:51.405Z  INFO wings: Configuring user pterodactyl (id: 999) as the owner of all server files.
04:24:51.413Z  INFO wings: Configuring timezone file location...
04:24:51.414Z  INFO wings: Checking container networking environment...
04:24:51.425Z  INFO wings: Found network interface for daemon: pterodactyl_nw
04:24:51.425Z  INFO wings: Ensuring correct network interface for containers...
04:24:51.440Z  INFO wings: Networking gateway detected as 172.18.0.1 for interface: pterodactyl0.
04:24:51.444Z  INFO wings: Contacting panel to retrieve a list of currrent Eggs available to the node.
04:24:51.474Z  INFO wings: Checking existing eggs against Panel response...
04:24:51.479Z  INFO wings: Beginning server initialization process.
(node:13595) UnhandledPromiseRejectionWarning: Error: Callback was already called.
    at /srv/daemon/node_modules/async/dist/async.js:966:32
    at /srv/daemon/node_modules/async/dist/async.js:3885:13
    at initContainer.err (/srv/daemon/src/controllers/server.js:91:32)
    at docker.Docker (/srv/daemon/src/controllers/server.js:131:24)
    at process._tickCallback (internal/process/next_tick.js:68:7)
(node:13595) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:13595) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
04:24:51.724Z  INFO wings: Configuring websocket for daemon stats...
04:24:51.724Z  INFO wings: Configuring internal SFTP server...

[parkervcp]

What folder was linked to where? I am looking for exact information. Also was this a symbolic link or a hard link? There is a huge difference here.

[Lucavon]

@parkervcp I had this issue, I'm using a simple symbolic link, pointing /srv/daemon-data to /drives/main-hdd/pterodactyl/daemon-data.

I noticed that my sFTP bit of the config was still pointing at /srv/daemon-data; changing it to the actual path, /drives/main-hdd/pterodactyl/daemon-data, fixed the issue, the daemon is working.

Here's the part of the config:
OLD, Causing the issue everyone in here had:
"sftp": { "path": "/srv/daemon-data", "ip": "0.0.0.0", "port": 2022, "keypair": { "bits": 2048, "e": 65537 } },
Fixed, issue resolved:
"sftp": { "path": "/drives/main-hdd/pterodactyl/daemon-data", "ip": "0.0.0.0", "port": 2022, "keypair": { "bits": 2048, "e": 65537 } },

It seems like your sFTP implementation can't deal with symbolic links and will throw this obscure error.

Some system information:
OS: Arch Linux; everything up to date
Node: 10.0.0
NPM: 6.5.0

I know Arch isn't officially supported, but it works for me (after I made a slight change to the install script). Hopefully this can help you resolve the issue!

[parkervcp]

I am going to go out and say this then. If you need to use a non-standard folder you should set the correct folder when you set up the node, so that everything is in the right place.

[Sapd]

A UNIX application should definitely handle symlinks correctly. I wound't say that using symlinks isn't a correct way to set things up.

[parkervcp]

I wasn't saying that was the fix but how it "should" be done. I completely agree that it should have dealt with symlinks correctly.

[DaneEveritt]

@Lucavon any idea if this happens using the standalone SFTP server? I'm leaning heavily towards not fixing this and just doing a new daemon breaking release that completely removes the Nodejs based internal SFTP system and uses only the standalone one.

[Lucavon]

@DaneEveritt I just tested it (changed config/core.json to use the broken path again, remade the symlink, disabled the internal JS sftp server and used your standalone one) and it broke again.

Apr 28 16:31:05 lucaserver node[7560]: (node:7560) UnhandledPromiseRejectionWarning: Error: Callback was already called. Apr 28 16:31:05 lucaserver node[7560]: at /srv/daemon/node_modules/async/dist/async.js:966:32 Apr 28 16:31:05 lucaserver node[7560]: at /srv/daemon/node_modules/async/dist/async.js:3885:13 Apr 28 16:31:05 lucaserver node[7560]: at initContainer.err (/srv/daemon/src/controllers/server.js:91:32) Apr 28 16:31:05 lucaserver node[7560]: at docker.Docker (/srv/daemon/src/controllers/server.js:131:24) Apr 28 16:31:05 lucaserver node[7560]: at process._tickCallback (internal/process/next_tick.js:178:7) Apr 28 16:31:05 lucaserver node[7560]: (node:7560) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise whic> Apr 28 16:31:05 lucaserver node[7560]: (node:7560) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit> Apr 28 16:31:05 lucaserver node[7560]: {"name":"wings","hostname":"lucaserver","pid":7560,"level":30,"msg":"Configuring websocket for daemon stats...","time":"2019-04-28T14:31:05.980Z","v":0}

So no, the standalone SFTP server does not make a difference.

[DaneEveritt]

Well in that case its not an issue with SFTP specifically, its something else being shared most likely.

[BrainStone]

This also happened to me when using a symlink.

[parkervcp]

@BrainStone What about a hard link and not a symbolic link?

ln /origin /link versus ls -s /origin /link

[BrainStone]

I'd prefer not testing that right now, as it's a prodcution system.

[parkervcp]

I am just saying it's something to try. A hard link points to the hard drive where the files are. A symbolic link points to the original link that is a hard link.

[BrainStone]

Then I'm sure the hard link won't even work. The paths are on different partitions (hence I need the symlink in the first place)

[parkervcp]

Ah yeah. Then a hard link will fail yes

[DaneEveritt]

Won't fix, Nodejs daemon is in life-support only mode.