Reputation: 477
I have a Java 1.6 multi-threaded application (5-7 threads, most idle), which has a strange behavior.
The flow involves updating a device, with a 4-byte ID.
I hold the ID in a private byte-array. When the update succeeds, after ~4 seconds, the device sends a STATUS message, in which I compare it's ID with the one I'm holding, and clear the private bite-array and disable an error-timer.
All the work is done in a singleton class instance.
The strange behavior:
I print the value of the private byte-array from a method, which is called periodically.
Within the 4 seconds waiting for the STATUS message, the log displays a different ID (not garbage, but a 4-byte ID of a different object). Checking the value with a breakpoint shows this invalid value (meaning it's not a log error).
But, yet, when the STATUS message arrives, I compare the ID with the one I'l holding, and they match!
I moved the private member into a synchronized getter/setter, adding a log of the change, which doesn't catch the issue.
Here's a pseudo-code of my setter/getter and periodic status + the disturbing log:
public class Manager {
private volatile byte[] readerID = null;
public synchronized void setReaderID(byte[] readerID) {
this.readerID = readerID;
logger.debug("readerID = {}", StringUtilities.binaryToAscii(this.readerID));
}
public synchronized byte[] getReaderID() {
if (this.readerID == null)
return null;
return Arrays.copyOf(this.readerID, this.readerID.length);
}
/* Called every second */
public void periodicStatus() {
logger.debug("readerID = {}", StringUtilities.binaryToAscii(getReaderID()));
}
}
13:53:46,103|ad-5|INFO |Manager|readerUpdateFinish(): Received firmware install finish for reader 000189D0 at slot 0
13:53:46,103|ad-5|DEBUG|Manager|setReaderID(): readerID = 000189D0
13:53:46,103|ad-5|DEBUG|Manager|readerUpdateFinish(): triggered reader firmware timer, 1526986426103, 000189D0
13:53:46,408|ad-5|DEBUG|Manager|periodicStatus(): readerID = E69EAD03 // <- where's the setter???
13:53:50,030|ad-5|INFO |Manager|readerStatus(): Received status information for reader 000189D0 at slot 0
13:53:50,031|ad-5|DEBUG|Manager|setReaderID(): readerID = null
13:53:50,031|ad-5|DEBUG|Manager|readerStatus(): timer cleared, null
Any ideas?
Upvotes: -1
Views: 232
Reputation: 477
As Progman pointed out, readerID is passed by reference. It arrives from the transport-layer, held there as an instance-member, and is updated by the following incoming message, with the new ID, which is being displayed.
Upvotes: 0