Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

"Packet identifiers do not match" #11

Open
siilike opened this issue Jul 27, 2019 · 11 comments · May be fixed by #14
Open

"Packet identifiers do not match" #11

siilike opened this issue Jul 27, 2019 · 11 comments · May be fixed by #14
Assignees
@unreal4u
Labels
bug

Comments

@siilike
Copy link

siilike commented Jul 27, 2019

Using latest master, ActiveMQ Artemis and MAXIMUM=10 in example b4:

PHP Fatal error:  Uncaught unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php:96
Stack trace:
#0 /data1/tmp/mqtt/src/Protocol/PubRel.php(96): unreal4u\MQTT\Protocol\PubRel->controlPacketIdentifiers(Object(unreal4u\MQTT\Protocol\PubRec))
#1 /data1/tmp/mqtt/src/Client.php(307): unreal4u\MQTT\Protocol\PubRel->performSpecialActions(Object(unreal4u\MQTT\Client), Object(unreal4u\MQTT\Protocol\PubRec))
#2 /data1/tmp/mqtt/src/Protocol/Publish.php(367): unreal4u\MQTT\Client->processObject(Object(unreal4u\MQTT\Protocol\PubRec))
#3 /data1/tmp/mqtt/src/Client.php(307): unreal4u\MQTT\Protocol\Publish->performSpecialActions(Object(unreal4u\MQTT\Client), Object(unreal4u\MQTT\Application\EmptyWritableResponse))
#4 /data1/tmp/mqtt/src/Protocol/Publish.php(367): unreal4u\MQTT\Client->processObject(Object(unreal4u\MQTT\Protocol\PubRec))
#5 /data1/tmp/mqtt/src/Client.php(307): unreal4u\MQTT\Protocol\Publish->performSpecialActions(Object(unreal4u in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96

Fatal error: Uncaught unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96

unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96

Call Stack:
    0.0001     395376   1. {main}() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:0
    0.0200    1559032   2. unreal4u\MQTT\Protocol\Subscribe->loop() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:32
    5.4410    1700184   3. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Protocol/Subscribe.php:144
    5.4413    1709400   4. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4418    1713352   5. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4418    1713480   6. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4421    1714088   7. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4421    1714216   8. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4423    1714824   9. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4423    1714952  10. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4425    1715560  11. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4426    1715688  12. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4445    1726608  13. unreal4u\MQTT\Protocol\PubRel->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4445    1726608  14. unreal4u\MQTT\Protocol\PubRel->controlPacketIdentifiers() /data1/tmp/mqtt/src/Protocol/PubRel.php:96

The relevant identifiers are 1 and 57.

Artemis log:

2019-07-27 23:51:32,497 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(): IN << CONNECT protocol=(MQTT, 4), hasPassword=false, isCleanSession=false, keepAliveTimeSeconds=60, clientIdentifier=d1-subscribeOneTopic.php, hasUserName=false, isWillFlag=false
2019-07-27 23:51:32,498 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> CONNACK connectReturnCode=0, sessionPresent=true
2019-07-27 23:51:32,503 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): IN << SUBSCRIBE(50005)
	firstTest : EXACTLY_ONCE
2019-07-27 23:51:32,504 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> SUBACK(50005)
	2
2019-07-27 23:51:37,085 DEBUG [org.apache.activemq.artemis.core.protocol.mqtt] SESSION CREATED: 58b201cf-f0b8-4188-921c-14245fe2a0b4
2019-07-27 23:51:37,086 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(): IN << CONNECT protocol=(MQTT, 4), hasPassword=true, isCleanSession=false, keepAliveTimeSeconds=60, clientIdentifier=b4-publishMessageWithQoS2.php, hasUserName=true, userName=testuser, isWillFlag=false
2019-07-27 23:51:37,086 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> CONNACK connectReturnCode=0, sessionPresent=true
2019-07-27 23:51:37,090 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (1 / 10)
2019-07-27 23:51:37,093 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,093 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(52) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (1 / 10)
2019-07-27 23:51:37,095 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,095 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,097 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (2 / 10)
2019-07-27 23:51:37,099 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,099 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(53) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (2 / 10)
2019-07-27 23:51:37,100 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,100 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,102 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (3 / 10)
2019-07-27 23:51:37,104 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,104 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(54) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (3 / 10)
2019-07-27 23:51:37,106 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,106 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,109 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (4 / 10)
2019-07-27 23:51:37,110 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,111 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(55) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (4 / 10)
2019-07-27 23:51:37,112 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,112 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,113 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (5 / 10)
2019-07-27 23:51:37,115 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,116 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(56) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (5 / 10)
2019-07-27 23:51:37,117 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,117 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,119 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (6 / 10)
2019-07-27 23:51:37,122 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,122 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(57) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (6 / 10)
2019-07-27 23:51:37,122 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): IN << PUBREC(52)
2019-07-27 23:51:37,123 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,123 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,124 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(1)
2019-07-27 23:51:37,124 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(2)
2019-07-27 23:51:37,124 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(3)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(4)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(5)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(6)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(7)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(8)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(9)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(10)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(11)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (7 / 10)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(12)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(13)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(14)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(15)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(16)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(17)
2019-07-27 23:51:37,128 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,128 WARN  [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 50a0f810-b0b0-11e9-b862-28d2444cb448
2019-07-27 23:51:37,128 WARN  [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 50a0f810-b0b0-11e9-b862-28d2444cb448
2019-07-27 23:51:37,130 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,130 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,131 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (8 / 10)
2019-07-27 23:51:37,133 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,135 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,135 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,137 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (9 / 10)
2019-07-27 23:51:37,139 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,140 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,140 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,142 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (10 / 10)
2019-07-27 23:51:37,144 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,145 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,145 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,147 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << DISCONNECT
@unreal4u unreal4u self-assigned this Jul 27, 2019
@unreal4u unreal4u added the bug label Jul 27, 2019
@unreal4u
Copy link
Owner

Thanks for the extended logs, this will help me track down this bug!

I'll try to look at it ASAP.

@siilike
Copy link
Author

siilike commented Aug 6, 2019

Any updates on this?

@unreal4u
Copy link
Owner

unreal4u commented Aug 8, 2019

Hi @siilike : I haven't been able to look at this yet, will do so ASAP.

@siilike
Copy link
Author

siilike commented Aug 8, 2019

Here's the subscriber log:

[2019-08-08 22:48:31] Protocol\Subscribe.DEBUG: ++Loop++ [] []
[2019-08-08 22:48:31] Client.DEBUG: Checking time difference {"secondsDifference":5,"keepAlivePeriod":60} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":1,"isLocked":false} []
[2019-08-08 22:48:31] Protocol\Subscribe.DEBUG: Event received {"ordValue":60,"length":1} []
[2019-08-08 22:48:31] Internals\EventManager.INFO: Found a matching object, instantiating {"type":"unreal4u\\MQTT\\Protocol\\Publish","controlPacketNumber":3} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":1,"isLocked":false} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":34,"isLocked":false} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting QoS level {"bitString":60,"incomingQoSLevel":2} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: QoS level above 0, shifting message start position and getting packet identifier [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined packet identifier {"PI":408} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Analyzing first byte ["00111100"] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting redelivery bit [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined headers {"topicSize":9,"QoSLevel":2,"isDuplicate":true,"isRetained":false} []
[2019-08-08 22:48:31] Protocol\Subscribe.DEBUG: ++Loop++ [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Responding with PubRec {"qosLevel":2} []
[2019-08-08 22:48:31] Client.DEBUG: Validating object {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Client.INFO: About to send data {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created variable header {"variableHeader":"AZg="} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created payload {"payload":""} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Creating fixed header with values {"controlPacketValue":5,"specialFlags":0,"variableHeaderLength":2,"composed":"0"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created fixed header {"fixedHeader":"UAI="} []
[2019-08-08 22:48:31] Client.DEBUG: Sent data to socket {"writtenBytes":4,"sizeOfString":4} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":true} []
[2019-08-08 22:48:31] Client.DEBUG: Reading header from response [] []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":4,"isLocked":true} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":false} []
[2019-08-08 22:48:31] Protocol\PubRec.INFO: String of incoming data confirmed, returning new object {"callee":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Internals\EventManager.INFO: Found a matching object, instantiating {"type":"unreal4u\\MQTT\\Protocol\\Publish","controlPacketNumber":3} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":32,"isLocked":false} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting QoS level {"bitString":60,"incomingQoSLevel":2} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: QoS level above 0, shifting message start position and getting packet identifier [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined packet identifier {"PI":409} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Analyzing first byte ["00111100"] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting redelivery bit [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined headers {"topicSize":9,"QoSLevel":2,"isDuplicate":true,"isRetained":false} []
[2019-08-08 22:48:31] Client.DEBUG: Checking stack and performing special operations {"originObject":"unreal4u\\MQTT\\Protocol\\PubRec","responseObject":"unreal4u\\MQTT\\Protocol\\Publish"} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Responding with PubRec {"qosLevel":2} []
[2019-08-08 22:48:31] Client.DEBUG: Validating object {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Client.INFO: About to send data {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created variable header {"variableHeader":"AZk="} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created payload {"payload":""} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Creating fixed header with values {"controlPacketValue":5,"specialFlags":0,"variableHeaderLength":2,"composed":"0"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created fixed header {"fixedHeader":"UAI="} []
[2019-08-08 22:48:31] Client.DEBUG: Sent data to socket {"writtenBytes":4,"sizeOfString":4} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":true} []
[2019-08-08 22:48:31] Client.DEBUG: Reading header from response [] []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":4,"isLocked":true} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":false} []
[2019-08-08 22:48:31] Protocol\PubRec.INFO: String of incoming data confirmed, returning new object {"callee":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Internals\EventManager.INFO: Found a matching object, instantiating {"type":"unreal4u\\MQTT\\Protocol\\PubRel","controlPacketNumber":6} []
[2019-08-08 22:48:31] Protocol\PubRel.DEBUG: Determined packet identifier {"PI":"[object] (unreal4u\\MQTT\\DataTypes\\PacketIdentifier: \u0000\u0001)"} []
[2019-08-08 22:48:31] Client.DEBUG: Checking stack and performing special operations {"originObject":"unreal4u\\MQTT\\Protocol\\PubRec","responseObject":"unreal4u\\MQTT\\Protocol\\PubRel"} []
[2019-08-08 22:48:31] Client.DEBUG: Origin packet found, returning it {"originKey":5} []
1, 409
PHP Fatal error:  Uncaught unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php:96
Stack trace:
#0 /data1/tmp/mqtt/src/Protocol/PubRel.php(96): unreal4u\MQTT\Protocol\PubRel->controlPacketIdentifiers(Object(unreal4u\MQTT\Protocol\PubRec))
#1 /data1/tmp/mqtt/src/Client.php(307): unreal4u\MQTT\Protocol\PubRel->performSpecialActions(Object(unreal4u\MQTT\Client), Object(unreal4u\MQTT\Protocol\PubRec))
#2 /data1/tmp/mqtt/src/Protocol/Publish.php(367): unreal4u\MQTT\Client->processObject(Object(unreal4u\MQTT\Protocol\PubRec))
#3 /data1/tmp/mqtt/src/Client.php(307): unreal4u\MQTT\Protocol\Publish->performSpecialActions(Object(unreal4u\MQTT\Client), Object(unreal4u\MQTT\Application\EmptyWritableResponse))
#4 /data1/tmp/mqtt/src/Protocol/Publish.php(367): unreal4u\MQTT\Client->processObject(Object(unreal4u\MQTT\Protocol\PubRec))
#5 /data1/tmp/mqtt/src/Protocol/Subscribe.php(144): unreal4u\MQTT\Protocol\Publish->performSpecialActions(Obj in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96

Fatal error: Uncaught unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96

unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96

Call Stack:
    0.0002     395952   1. {main}() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:0
    0.1695    1833848   2. unreal4u\MQTT\Protocol\Subscribe->loop() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:38
    4.5293    1910392   3. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Protocol/Subscribe.php:144
    4.5298    1931040   4. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    4.5340    1936112   5. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    4.5342    1936408   6. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    4.5373    1950840   7. unreal4u\MQTT\Protocol\PubRel->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    4.5373    1950840   8. unreal4u\MQTT\Protocol\PubRel->controlPacketIdentifiers() /data1/tmp/mqtt/src/Protocol/PubRel.php:96

@unreal4u
Copy link
Owner

Thanks!

[2019-08-08 22:48:31] Protocol\PubRel.DEBUG: Determined packet identifier {"PI":"[object] (unreal4u\\MQTT\\DataTypes\\PacketIdentifier: \u0000\u0001)"} []

That line is extremely strange, that should be an int and not some unicode characters. My best guess is that the internal counter for the message is off, this could have been introduced during the fix for #9.

I'll try it out and let you know.

You just ran the example file?

Can you confirm that running https://github.com/unreal4u/mqtt/releases/tag/v1.1.0 this version everything is ok? (It will fail however if the message is over 127 bytes, but that is another issue).

Greetings.

@siilike
Copy link
Author

siilike commented Aug 27, 2019

Still same issue. I only changed MAXIMUM=10 in b4-publishMessageWithQoS2.php. It works when sleeping between messages, so the issue is how multiple messages are received.

It's easy to test, just get ActiveMQ Artemis, run "bin/artemis create brokertest --user test --password test --allow-anonymous" to create a broker and then "brokertest/bin/artemis run".

@siilike
Copy link
Author

siilike commented Oct 19, 2019

Ping. This is probably the best PHP MQTT library, but unusable when this bug is present.

@unreal4u
Copy link
Owner

Hi, I have vacations now, so I'm finally able to take a look at this bug. Sorry for the delay but it's been quite busy lately.

@PFRene
Copy link

PFRene commented Sep 8, 2020 •
edited
Loading

Hello, I was wondering about the status of this bug? I love this package, but at the moment it's consistently crashing for me. It's fairly easily reproducible too : if you change MAXIMUM from 1 to 10 in the publishMessageWithQoS2 example, and at the same time have the subscribeMultipleTopics running, you'll see it crash after about 1 or 2 messages, in fact, sometimes it fails to process any messages at all. So it definitely seems to struggle when processing > 1 messages.

I'm not clever enough to attempt to fix it myself :)

@unreal4u
Copy link
Owner

Hi @PFRene !

I haven't have made the time yet to fix this, but I have a pretty good idea of where the bug actually is and what I need to do to fix it. It is a not so obvious bug and pretty difficult to fix it in an appropriate manner.

I will be working again soon on this library! Sorry and thanks for the patience!

@PFRene
Copy link

PFRene commented Sep 10, 2020

Your work is much appreciated - looking forward to future updates!

@unreal4u unreal4u linked a pull request Sep 22, 2020 that will close this issue
Draft
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@unreal4u unreal4u

Labels
bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Correct handling of qos level2 messages unreal4u/mqtt
3 participants
@unreal4u @siilike @PFRene