search

philippe44 / LMS-uPnP

Integrate UPnP players with LogitechMediaServer
111 stars 17 forks source link

Feature Request: Error log output when cannot bind to port. & Log at first run #51

Closed Cisor closed 3 years ago

Cisor commented 3 years ago

Issue When attempting to run for the first time, if a port that UPnPBridge bridge wants to use is already attached to another process, it crashes without a useful error.

Understandably, it seems that before the first successful launch the "Enable" Logging option isn't respected. -d all=sdebug "Extra command line options" doesn't seem to have any effect either.

It was only a flash of inspiration that led me to think of the conflicting ports!

After a successful run enabling the logging, the error is still quite vague [12:18:39.829594] Start:1516 UPnP init failed: -203

Request

  1. On first run, (possibly detectable by the lack of a config file) assume by default that logging should be enabled. Otherwise respect the config file logging choice.
  2. Catch the specific error condition of failing to bind to a port and log a descriptive error in place of Start:1516 UPnP init failed: -203

Environment

Server log from attempted first run is pasted below, as at this stage no upnpbridge.log file exists

==> Logs/server.log <== [21-05-24 22:13:21.6520] main::init (353) Starting Logitech Media Server (v7.7.6, 1452060463, Thu Jan 21 02:17:04 UTC 2016) perl 5.024000 [21-05-24 22:13:22.9114] Slim::Utils::Misc::msg (1315) Warning: [22:13:22.9108] /volume1/@appstore/SqueezeCenter/Cache/cookies.dat does not seem to contain cookies at /volume1/@appstore/SqueezeCenter/CPAN/HTTP/Cookies.pm line 426. [21-05-24 22:13:24.4361] Slim::Utils::SQLiteHelper::postConnect (359) Optimizing DB because of missing or empty sqlite_stat1 table [21-05-24 22:13:25.4897] Slim::Schema::init (162) Warning: Creating new database - empty, outdated or invalid database found [21-05-24 22:13:27.9118] main::checkDataSource (1071) Warning: Schema updated or no media found in the database, initiating scan. [21-05-24 22:13:37.1859] Slim::Utils::SQLiteHelper::postConnect (359) Optimizing DB because of missing or empty sqlite_stat1 table [21-05-24 22:51:47.9725] main::init (353) Starting Logitech Media Server (v7.7.6, 1452060463, Thu Jan 21 02:17:04 UTC 2016) perl 5.024000 [21-05-24 22:51:48.7513] Slim::Utils::SQLiteHelper::postConnect (359) Optimizing DB because of missing or empty sqlite_stat1 table [21-05-24 22:51:51.3470] main::checkDataSource (1071) Warning: Schema updated or no media found in the database, initiating scan. [21-05-24 22:56:14.4079] main::init (353) Starting Logitech Media Server (v7.7.6, 1452060463, Thu Jan 21 02:17:04 UTC 2016) perl 5.024000 [21-05-24 22:56:26.2852] Slim::Utils::SQLiteHelper::postConnect (359) Optimizing DB because of missing or empty sqlite_stat1 table [21-05-24 22:56:29.7188] Plugins::UPnPBridge::Queries::initQueries (41) Unable to load ImageProxy, consider moving to >7.8 [21-05-24 22:57:35.4554] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 22:58:05.4706] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 22:58:24.9595] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9575] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 121. [21-05-24 22:58:24.9611] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9607] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 127. [21-05-24 22:58:24.9650] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9617] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 133. [21-05-24 22:58:24.9683] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9680] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 205. [21-05-24 22:58:24.9721] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9718] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 266. [21-05-24 22:58:24.9738] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9735] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 277. [21-05-24 22:58:24.9747] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9744] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 283. [21-05-24 22:58:24.9763] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9760] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 291. [21-05-24 22:58:24.9771] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9769] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 297. [21-05-24 22:58:24.9780] Slim::Utils::Misc::msg (1315) Warning: [22:58:24.9777] Use of uninitialized value in concatenation (.) or string at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/UPnPBridge/HTML/EN/plugins/UPnPBridge/settings/basic.html line 310. [21-05-24 22:58:35.4845] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 22:59:05.5503] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 22:59:35.5580] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 23:00:05.5654] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 23:00:35.5737] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 23:01:05.5927] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 23:01:35.6167] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 23:02:05.7184] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting [21-05-24 23:02:36.8028] Plugins::UPnPBridge::Squeeze2upnp::beat (189) crashed ... restarting

philippe44 commented 3 years ago

The "init failed" is an error log that will always be logged. It's not that -d all=sdebug is not honored, it's just that there is nothing more to log as the error happens very early in the startup process. I can add an extra message in case of "port in use" error. I've not verified what binding failed, but did you change the UPnP port (49152).

Other than that, you should really move away from LMS 7.7.6. It's insanely old and is not considered viable anymore. In fact, you should only use 8.1.x or the nightly 8.2

Cisor commented 3 years ago

Commenting this time with my personal rather than corporate account!! #AgeAddledBrain

I really appreciate you responding so quickly. Thank you

During my debugging, I tried the old version to check if it was a newly introduced issue. I'll upgrade again shortly now I know that it was an environmental issue!

The conflicted binding was to port 1900. When upnpbridge is running correctly, the command netstat -tulpn does not show LISTEN, but is listed against the process. If you could add an error showing that it's a binding issue that would be very helpful indeed! My age addled brain will no doubt have forgotten this entire conversation by the next time I'm reinstalling!

philippe44 commented 3 years ago

The conflicted binding was to port 1900. When upnpbridge is running correctly, the command netstat -tulpn does not show LISTEN, but is listed against the process. If you could add an error showing that it's a binding issue that would be very helpful indeed! My age addled brain will no doubt have forgotten this entire conversation by the next time I'm reinstalling!

I'll do that

philippe44 commented 3 years ago

Done