OBC reporting "illegal reflective access operation" (and more) etc on RP4 when starting up

[mattpstv]

After opening the file open-beat-control-0.1.0-Preview.jar on my networked RP4, the following messages appear and eventually continue scrolling until it times out. I assume it has something to do with thinking Rekordbox is open via Link on the network, but all that is connected are two xdj-1000mk2s and a DJS-1000. I can more systematically test this for you if the problem isn't something obvious. Possibly related is a similar problem opening OBC on my macbook:

ps. I know this issue format is a mess. I'll clean it up later or if this is a non-issue it will be deleted and not matter. Reading up on proper issue opening formatting now. m+

***@PSTVPI:~/Downloads $ java -jar open-beat-control-0.1.0-Preview.jar 2020-Jan-22 20:14:52 INFO [open-beat-control.logs:87] - Open Beat Control version 0.1.0-SNAPSHOT-62-0xdec7 built Mon Jan 20 00:30:32 UTC 2020 2020-Jan-22 20:14:52 INFO [open-beat-control.logs:88] - Java version 11.0.2-BellSoft, OpenJDK Server VM, BellSoft 2020-Jan-22 20:14:52 INFO [open-beat-control.logs:89] - Operating system version Linux 4.19.75-v7l+ WARNING: An illegal reflective access operation has occurred WARNING: Illegal reflective access by clojure.lang.InjectedInvoker/0x72aabc28 (file:/home/pi/Downloads/open-beat-control-0.1.0-Preview.jar) to method sun.nio.ch.DatagramSocketAdaptor.bind(java.net.SocketAddress) WARNING: Please consider reporting this to the maintainers of clojure.lang.InjectedInvoker/0x72aabc28 WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations WARNING: All illegal access operations will be denied in a future release 2020-Jan-22 20:14:52 INFO [open-beat-control.core:179] - Running OSC server on port 17002 2020-Jan-22 20:14:53 INFO [open-beat-control.core:190] - Waiting for Pro DJ Link devices... 2020-Jan-22 20:14:54 INFO [open-beat-control.core:200] - Pro DJ Link Device Found: DeviceAnnouncement[device:1, name:DJS-1000, address:192.168.7.229] 2020-Jan-22 20:14:54 INFO [open-beat-control.core:200] - Pro DJ Link Device Found: DeviceAnnouncement[device:3, name:XDJ-1000MK2, address:192.168.7.197] 2020-Jan-22 20:14:54 INFO [open-beat-control.core:200] - Pro DJ Link Device Found: DeviceAnnouncement[device:4, name:XDJ-1000MK2, address:192.168.7.211] 2020-Jan-22 20:14:54 INFO [org.deepsymmetry.beatlink.VirtualCdj:588] - Found matching network interface eth0 (eth0), will use address /192.168.7.203/22 [/192.168.7.255] 2020-Jan-22 20:14:54 INFO [open-beat-control.core:200] - Pro DJ Link Device Found: DeviceAnnouncement[device:17, name:rekordbox, address:192.168.7.246]

2020-Jan-22 20:10:58 WARN [org.deepsymmetry.beatlink.CdjStatus:585] - Received CDJ status packet with reported payload length of 292 and actual payload length of 256 2020-Jan-22 20:13:03 INFO [open-beat-control.core:121] - Virtual CDJ running as Player 5 2020-Jan-22 20:13:03 INFO [open-beat-control.core:121] - Virtual CDJ running as Player 5 2020-Jan-22 20:13:03 WARN [org.deepsymmetry.beatlink.Util:216] - Do not know any Pro DJ Link packets received on port 50002 with type 0x10. 2020-Jan-22 20:13:03 WARN [org.deepsymmetry.beatlink.VirtualCdj:343] - Ignoring unrecognized packet sent to update port. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:351] - Processing device found, number:3, name:"XDJ-1000MK2". 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:351] - Processing device found, number:17, name:"rekordbox". 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:354] - Recording rekordbox collection mount. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:884] - Reporting media mounted in SlotReference[player:3, slot:USB_SLOT] 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.dbserver.ConnectionManager:308] - Player 17 doesn't answer rekordbox port queries, connection refused, not yet ready? 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.dbserver.ConnectionManager:308] - Player 1 doesn't answer rekordbox port queries, connection refused, not yet ready? 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:884] - Reporting media mounted in SlotReference[player:17, slot:COLLECTION] 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.CrateDigger:91] - CrateDigger starting because MetadataFinder[running:true, passive:false, loadedTracks:{}, mountedMediaSlots:[], mountedMediaDetails:[], metadataCacheFiles:{}] has. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:351] - Processing device found, number:4, name:"XDJ-1000MK2". 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:351] - Processing device found, number:1, name:"DJS-1000". 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:884] - Reporting media mounted in SlotReference[player:3, slot:CD_SLOT] 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.CrateDigger:319] - Fetching rekordbox export.pdb from player 3, slot USB_SLOT 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.MetadataFinder:884] - Reporting media mounted in SlotReference[player:4, slot:CD_SLOT] 2020-Jan-22 20:13:03 WARN [org.deepsymmetry.beatlink.CdjStatus:585] - Received CDJ status packet with reported payload length of 292 and actual payload length of 256 2020-Jan-22 20:13:03 ERROR [org.deepsymm

etry.beatlink.data.MetadataFinder:124] - Problem requesting metadata, returning null java.lang.Thread.run Thread.java: 834 org.deepsymmetry.beatlink.data.MetadataFinder$7.run MetadataFinder.java: 1312 org.deepsymmetry.beatlink.data.MetadataFinder.access$500 MetadataFinder.java: 39 org.deepsymmetry.beatlink.data.MetadataFinder.requestMetadataInternal MetadataFinder.java: 122 org.deepsymmetry.beatlink.dbserver.ConnectionManager.invokeWithClientSession ConnectionManager.java: 192 org.deepsymmetry.beatlink.dbserver.ConnectionManager.allocateClient ConnectionManager.java: 116 org.deepsymmetry.beatlink.dbserver.ConnectionManager.chooseAskingPlayerNumber ConnectionManager.java: 424 java.lang.IllegalStateException: No player number available to query player 3. If such a player is present on the network, it must be using Link to play a track from our target player, so we can't steal its channel number.

2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.CrateDigger:324] - Finished fetching export.pdb from player 3, slot USB_SLOT; received 270.3 kB in 319ms, 847.4 kB/s. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:273] - Indexed 75 Tracks. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:315] - Indexed 19 Artists. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:357] - Indexed 8 Colors. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:409] - Indexed 20 Albums. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:451] - Indexed 13 Labels. 2020-Jan-22 20:13:03 WARN [org.deepsymmetry.beatlink.CdjStatus:585] - Received CDJ status packet with reported payload length of 292 and actual payload length of 256 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:493] - Indexed 19 Musical Keys. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:535] - Indexed 9 Genres. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:561] - Indexed 63 Artwork Paths. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:637] - Indexed 1 playlists. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.cratedigger.Database:668] - Indexed 1 playlist folders. 2020-Jan-22 20:13:03 INFO [org.deepsymmetry.beatlink.data.CrateDigger:331] - Parsing database took 167ms, 449 tracks/s 2020-Jan-22 20:13:04 WARN [org.deepsymmetry.beatlink.CdjStatus:585] - Received CDJ status packet with reported payload length of 292 and actual payload length of 256 2020-Jan-22 20:13:04 WARN [org.deepsymmetry.beatlink.data.CueList:525] - Was expecting embedded color java.awt.Color[r=0,g=255,b=0] for rekordbox color code 0, but found color java.awt.Color[r=26,g=255,b=0] 2020-Jan-22 20:13:04 WARN [org.deepsymmetry.beatlink.data.CueList:525] - Was expecting embedded color java.awt.Color[r=0,g=255,b=0] for rekordbox color code 0, but found color java.awt.Color[r=26,g=255,b=0] 2020-Jan-22 20:13:04 INFO [org.deepsymmetry.beatlink.dbserver.ConnectionManager:308] - Player 17 doesn't answer rekordbox port queries, connection refused, not yet ready? 2020-Jan-22 20:13:04 INFO [org.deepsymmetry.beatlink.dbserver.ConnectionManager:308] - Player 1 doesn't answer rekordbox port queries, connection refused, not yet ready? 2020-Jan-22 20:13:04 WARN [org.deepsymmetry.beatlink.CdjStatus:585] - Received CDJ status packet with reported payload length of 292 and actual payload length of 256 2020-Jan-22 20:13:04 WARN [org.deepsymmetry.beatlink.data.CueList:525] - Was expecting embedded color java.awt.Color[r=0,g=255,b=0] for rekordbox color code 0, but found color java.awt.Color[r=26,g=255,b=0] 2020-Jan-22 20:13:04 WARN [org.deepsymmetry.beatlink.data.CueList:525] - Was expecting embedded color java.awt.Color[r=0,g=255,b=0] for rekordbox color code 0, but found color java.awt.Color[r=26,g=255,b=0] 2020-Jan-22 20:13:04 WARN [org.deepsymmetry.beatlink.data.CueList:525] - Was expecting embedded color java.awt.Color[r=0,g=255,b=0] for rekordbox color code 0, but found color java.awt.Col

[brunchboy]

Hi, @mattpstv thanks for opening this. It sounds like there are a lot of different things you are reporting, could you separate them all each into their own issues? And let me know if anything is actually not working? A lot of this looks like just normal noise. For example:

• The illegal reflective operation is something you are going to see for years (or possibly forever), until Clojure and all of the Java libraries that I use are updated to behave nicely with Project Jigsaw, the module system that was introduced with Java 9. That may never happen, and I have no control over it.

• The error about an address already in use is something you are going to have to troubleshoot at your end. It sounds like you have another process that is already listening on the port number that you are trying to have Open Beat Control use. You can use lsof to see what processes have what ports open. For example, to see what process is using the port 17002 that OBC defaults to trying to listen for OSC commands on, which is what the stack trace is reporting as the problem, lsof -i :17002

• The report about being unable to find a player number to use to query the database will happen if you have only one physical player on the network (or only one has been seen by Beat Link so far), you have not configured Beat Link to use a real player number (from 1 to 4), and not enough time has passed yet for Crate Digger to download the exported media database to get metadata that way. So that should clear up on its own shortly after startup (or media insertion), or you can prevent it completely by configuring Open Beat Control to use a real player number.

• Stuff about unexpected colors is just a matter of the world not yet fully understanding how to parse cue database entries. They are harmless, but if you would like to dig into that by examining packet captures and the project dysentery protocol analysis document, pull requests there (and in Beat Link itself) would be most welcome.

• The thing about your player lying about the size of its status packets is a somewhat disconcerting sign of quality control at the Pioneer end, and of the engineers there not fully understanding the protocol they are suposed to be implementing, but I doubt they have a forum where you can open issues. I will try to suppress the repetitions, at least; we only need to hear about it once. I do similar things for other kinds of protocol misadventures.

So, other than figuring out who is using your port, is there anything that is actually not working? And other than potentially squelching repetitions of the malformed status packet length field, are there any issues for me to work on?

[brunchboy]

All right, I have been investigating the stream of status packet size warnings, and I can tell you the mistake the Pioneer engineers seem to have made: it looks like they subtracted the packet header size twice when computing the payload size! But I am working on adding code to Beat Link to only report that warning once for each combination of expected and actual size.

[brunchboy]

Ok! I have deployed a new snapshot build of the Beat Link library to Sonatype that should report this warning only once, and I am kicking off the GitHub Actions workflow to update the Open Beat Control snapshot, which will pick up that change, so that should go away. Please let me know if there are any other issues left for me to investigate from this report, or close it. (Either way, I would appreciate hearing about what process was tying up the default Open Beat Control OSC server port on your MacBook!)

[brunchboy]

In case you’re curious about why I am so pessimistic that we will ever get rid of the illegal reflective access warnings, here is a really informative, concise summary: https://blog.frankel.ch/hard-look-state-java-modularization/ (the short comment thread is packed with insight as well).

I personally feel it’s nearly even odds right now that rather than ever releasing a version that enforces the restrictions that warning is talking about, they will instead give up on the idea entirely and stop warning.

[brunchboy]

@mattpstv are there any actual problems here, especially using my latest snapshots? I haven’t heard anything back, and unless I do soon, I am going to close the issue.

[brunchboy]

Closing for lack of update about concrete problems.