java instance member corruption

Question

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?

Answer 1

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.