Actions
Bug #2373
openSMS sent to old Nokia 1100: "message 0x332/1" causes CP-ERROR, and SMS is received 5 or more times
Added by neels almost 7 years ago. Updated over 5 years ago.
Status:
New
Priority:
Low
Assignee:
-
Category:
-
Target version:
-
Start date:
07/17/2017
Due date:
% Done:
0%
Resolution:
Spec Reference:
Description
When I'm using an old Nokia 1100 (and our AoIP branch, which shouldn't make a difference) to receive an SMS, each reception works and is displayed by the phone, but OsmoMSC complains about an unhandled message type, returns a CP-ERROR and resends the SMS N times:
20170717221627459 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:545 SMC(30) message 0x332/1 unhandled at this state WAIT_CP_ACK. 20170717221627459 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:552 SMC(30) RX Unimplemented CP msg_type: 0x332 20170717221627459 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:139 SMC(30) new CP state WAIT_CP_ACK -> IDLE 20170717221627459 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:150 SMC(30) TX CP-ERROR, cause 97 (Message Type doesn't exist)
Files
| nokia1100_cp-error.pcap | nokia1100_cp-error.pcap | 2.05 KB | neels, 07/17/2017 08:37 PM |
Updated by neels almost 7 years ago
- File nokia1100_cp-error.pcap nokia1100_cp-error.pcap added
OsmoMSC log output which matches the attached pcap
20170717221251141 DRLL <0000> ../../../src/libmsc/gsm_04_08.c:3632 Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
20170717221251141 DRR <0003> ../../../src/libmsc/gsm_04_08.c:1090 PAGING RESPONSE: MI(IMSI)=901700000014701
20170717221251141 DREF <000e> ../../../src/libmsc/subscr_conn.c:335 unknown: MSC conn use + 1 == 2
20170717221251141 DMM <0002> ../../src/fsm.c:229 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_INIT}: Allocated
20170717221251141 DMM <0002> ../../../src/libmsc/subscr_conn.c:344 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
20170717221251141 DMM <0002> ../../../src/libmsc/subscr_conn.c:66 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
20170717221251141 DVLR <001e> ../../src/fsm.c:229 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: Allocated
20170717221251141 DVLR <001e> ../../src/fsm.c:259 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000014701)[0x739180]
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:686 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:712 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
20170717221251141 DREF <000e> ../../../src/libvlr/vlr_access_req_fsm.c:348 VLR subscr MSISDN:701 usage increases to: 6
20170717221251141 DREF <000e> ../../../src/libmsc/gsm_04_08.c:3853 VLR subscr MSISDN:701 usage increases to: 7
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:319 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:284 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:251 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:223 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:209 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:194 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:173 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:185 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:108 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
20170717221251141 DVLR <001e> ../../../src/libvlr/vlr_access_req_fsm.c:118 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
20170717221251141 DMM <0002> ../../../src/libvlr/vlr_access_req_fsm.c:157 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
20170717221251141 DMM <0002> ../../../src/libmsc/subscr_conn.c:77 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
20170717221251141 DMM <0002> ../../../src/libmsc/subscr_conn.c:84 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
20170717221251141 DMSC <000a> ../../../src/libmsc/sms_queue.c:424 Pending paging while subscriber 901700000014701 attached.
20170717221251141 DPAG <0007> ../../../src/libmsc/gsm_subscriber.c:70 Paging success for MSISDN:701 (event=0)
20170717221251141 DPAG <0007> ../../../src/libmsc/osmo_msc.c:325 Paging can stop for MSISDN:701
20170717221251141 DPAG <0007> ../../../src/libmsc/gsm_subscriber.c:94 Calling paging cbfn.
20170717221251141 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:975 paging_cb_send_sms(hooknum=1, event=0, msg=(nil),conn=0x73a0e0, sms=0x733b00/id: 27)
20170717221251141 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:903 gsm411_send_sms()
20170717221251141 DCC <0001> ../../../src/libmsc/transaction.c:89 subscr=0x725f10, net=0x66f650
20170717221251141 DREF <000e> ../../../src/libmsc/transaction.c:95 VLR subscr MSISDN:701 usage increases to: 8
20170717221251141 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:93 SMC(27) instance created for network
20170717221251141 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:89 SMR(27) instance created for network.
20170717221251141 DREF <000e> ../../../src/libmsc/gsm_04_11.c:923 MSISDN:701: MSC conn use + 1 == 3
20170717221251141 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:956 TX: SMS DELIVER
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:419 SMR(27) message SM-RL-DATA_REQ received in state IDLE
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:219 SMR(27) TX SMS RP-DATA
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:143 SMR(27) new RP state IDLE -> WAIT_FOR_RP_ACK
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:472 SMC(27) message MNSMS-EST-REQ received in state IDLE
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:139 SMC(27) new CP state IDLE -> MM_CONN_PENDING
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:572 SMC(27) message MMSMS-EST-CNF received in state MM_CONN_PENDING
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:186 SMC(27) send CP data
20170717221251151 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:139 SMC(27) new CP state MM_CONN_PENDING -> WAIT_CP_ACK
20170717221251151 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:145 sending CP message (trans=0)
20170717221251151 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:129 GSM4.11 TX 09 01 23 01 00 07 91 44 77 58 10 06 50 00 17 00 03 80 07 f2 00 00 71 70 71 02 21 15 00 09 d4 ba d9 8c 3e 9b cf 68
20170717221251151 DMSC <000a> ../../../src/libmsc/msc_ifaces.c:45 msc_tx 38 bytes to MSISDN:701 via RAN_GERAN_A
20170717221251151 DMSC <000a> ../../../src/libmsc/a_iface.c:136 Passing DTAP message from MSC to BSC (conn_id=6)
20170717221251151 DMSC <000a> ../../../src/libmsc/a_iface.c:144 Massage will be sent as BSSMAP DTAP message!
20170717221251151 DMSC <000a> ../../../src/libmsc/a_iface.c:146 N-DATA.req(6, 01 00 26 09 01 23 01 00 07 91 44 77 58 10 06 50 00 17 00 03 80 07 f2 00 00 71 70 71 02 21 15 00 09 d4 ba d9 8c 3e 9b cf 68 )
20170717221251151 DLSCCP <002e> ../../src/sccp_scoc.c:1613 Received SCCP User Primitive N-DATA.request)
20170717221251151 DLSCCP <002e> ../../src/sccp_scoc.c:1651 SCCP-SCOC(6)[0x733df0]{ACTIVE}: Received Event N-DATA.req
20170717221251151 DLSS7 <002d> ../../src/sccp_scrc.c:383 sccp_scrc_rx_scoc_conn_msg: HDR=(CO:CODT,V=0,LEN=0),
20170717221251151 DLSS7 <002d> ../../src/osmo_ss7_hmrt.c:192 m3ua_hmdc_rx_from_l2(): dpc=336=0.42.0 not local, message is for routing
20170717221251151 DLSS7 <002d> ../../src/osmo_ss7_hmrt.c:146 Found route for dpc=336=0.42.0: pc=0=0.0.0 mask=0x0 via AS as-clnt-OsmoMSC proto=m3ua
20170717221251151 DLSS7 <002d> ../../src/osmo_ss7_hmrt.c:151 rt->dest.as proto is M3UA for dpc=336=0.42.0
20170717221251151 DLSS7 <002d> ../../src/m3ua.c:505 XUA_AS(as-clnt-OsmoMSC)[0x726c80]{AS_ACTIVE}: Received Event AS-TRANSFER.req
20170717221251151 DREF <000e> ../../../src/libmsc/gsm_subscriber.c:103 VLR subscr MSISDN:701 usage decreases to: 7
20170717221251151 DMM <0002> ../../../src/libmsc/subscr_conn.c:132 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
20170717221251151 DMM <0002> ../../../src/libmsc/subscr_conn.c:164 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
20170717221251151 DREF <000e> ../../../src/libvlr/vlr_access_req_fsm.c:367 VLR subscr MSISDN:701 usage decreases to: 6
20170717221251151 DMM <0002> ../../../src/libmsc/osmo_msc.c:58 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
20170717221251151 DMM <0002> ../../../src/libmsc/subscr_conn.c:164 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
20170717221251151 DREF <000e> ../../../src/libmsc/osmo_msc.c:73 MSISDN:701: MSC conn use - 1 == 2
20170717221251151 DMSC <000a> ../../../src/libmsc/a_iface_bssap.c:322 User has been accepted by MSC.
20170717221251151 DLINP <0023> ../../src/stream.c:253 connected write
20170717221251151 DLINP <0023> ../../src/stream.c:178 sending data
20170717221251151 DLINP <0023> ../../src/stream.c:253 connected write
20170717221251151 DLINP <0023> ../../src/stream.c:178 sending data
20170717221251152 DLINP <0023> ../../src/stream.c:253 connected write
20170717221251152 DLINP <0023> ../../src/stream.c:178 sending data
20170717221252316 DLINP <0023> ../../src/stream.c:249 connected read
20170717221252316 DLINP <0023> ../../src/stream.c:163 message received
20170717221252317 DLSS7 <002d> ../../src/osmo_ss7.c:1451 asp-asp-clnt-OsmoMSC: xua_cli_read_cb(): sctp_recvmsg() returned 48 (flags=0x80)
20170717221252317 DLM3UA <0030> ../../src/m3ua.c:719 asp-asp-clnt-OsmoMSC: Received M3UA Message (XFER:DATA)
20170717221252317 DLM3UA <0030> ../../src/m3ua.c:539 asp-asp-clnt-OsmoMSC: m3ua_rx_xfer
20170717221252317 DLM3UA <0030> ../../src/m3ua.c:578 asp-asp-clnt-OsmoMSC: m3ua_rx_xfer(): M3UA data header: opc=336=0.42.0 dpc=1=0.0.1
20170717221252317 DLSS7 <002d> ../../src/osmo_ss7_hmrt.c:188 m3ua_hmdc_rx_from_l2(): found dpc=1=0.0.1 as local
20170717221252317 DLSS7 <002d> ../../src/sccp_scrc.c:434 scrc_rx_mtp_xfer_ind_xua: HDR=(CO:CODT,V=0,LEN=0),
20170717221252317 DLSCCP <002e> ../../src/sccp_scoc.c:1546 Received CO:CODT for local reference 6
20170717221252317 DLSCCP <002e> ../../src/sccp_scoc.c:1579 SCCP-SCOC(6)[0x733df0]{ACTIVE}: Received Event RCOC-DT1.ind
20170717221252317 DLSCCP <002e> ../../src/sccp_user.c:156 Delivering N-DATA.indication to SCCP User 'OsmoMSC-A'
20170717221252317 DMSC <000a> ../../../src/libmsc/a_iface.c:491 N-DATA.ind(6, 01 03 05 89 01 02 02 00 )
20170717221252317 DMSC <000a> ../../../src/libmsc/a_iface_bssap.c:80 Looking for A subscriber: conn_id 6
20170717221252317 DIUCS <001f> ../../../src/libmsc/a_iface_bssap.c:88 Found A subscriber for conn_id 6
20170717221252317 DMSC <000a> ../../../src/libmsc/a_iface_bssap.c:663 BSC sends layer 3 dtap (conn_id=6)
20170717221252317 DREF <000e> ../../../src/libmsc/osmo_msc.c:101 MSISDN:701: MSC conn use + 1 == 3
20170717221252317 DRLL <0000> ../../../src/libmsc/gsm_04_08.c:3632 Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
20170717221252317 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:812 receiving data (trans_id=0)
20170717221252317 DMM <0002> ../../../src/libmsc/subscr_conn.c:366 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
20170717221252317 DMM <0002> ../../../src/libmsc/subscr_conn.c:182 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:545 SMC(27) message 0x332/1 unhandled at this state WAIT_CP_ACK.
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:552 SMC(27) RX Unimplemented CP msg_type: 0x332
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:139 SMC(27) new CP state WAIT_CP_ACK -> IDLE
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:150 SMC(27) TX CP-ERROR, cause 97 (Message Type doesn't exist)
20170717221252317 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:145 sending CP message (trans=0)
20170717221252317 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:129 GSM4.11 TX 09 10 61
20170717221252317 DMSC <000a> ../../../src/libmsc/msc_ifaces.c:45 msc_tx 3 bytes to MSISDN:701 via RAN_GERAN_A
20170717221252317 DMSC <000a> ../../../src/libmsc/a_iface.c:136 Passing DTAP message from MSC to BSC (conn_id=6)
20170717221252317 DMSC <000a> ../../../src/libmsc/a_iface.c:144 Massage will be sent as BSSMAP DTAP message!
20170717221252317 DMSC <000a> ../../../src/libmsc/a_iface.c:146 N-DATA.req(6, 01 00 03 09 10 61 )
20170717221252317 DLSCCP <002e> ../../src/sccp_scoc.c:1613 Received SCCP User Primitive N-DATA.request)
20170717221252317 DLSCCP <002e> ../../src/sccp_scoc.c:1651 SCCP-SCOC(6)[0x733df0]{ACTIVE}: Received Event N-DATA.req
20170717221252317 DLSS7 <002d> ../../src/sccp_scrc.c:383 sccp_scrc_rx_scoc_conn_msg: HDR=(CO:CODT,V=0,LEN=0),
20170717221252317 DLSS7 <002d> ../../src/osmo_ss7_hmrt.c:192 m3ua_hmdc_rx_from_l2(): dpc=336=0.42.0 not local, message is for routing
20170717221252317 DLSS7 <002d> ../../src/osmo_ss7_hmrt.c:146 Found route for dpc=336=0.42.0: pc=0=0.0.0 mask=0x0 via AS as-clnt-OsmoMSC proto=m3ua
20170717221252317 DLSS7 <002d> ../../src/osmo_ss7_hmrt.c:151 rt->dest.as proto is M3UA for dpc=336=0.42.0
20170717221252317 DLSS7 <002d> ../../src/m3ua.c:505 XUA_AS(as-clnt-OsmoMSC)[0x726c80]{AS_ACTIVE}: Received Event AS-TRANSFER.req
20170717221252317 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:786 MNSMS-ERROR-IND, no cause
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:486 SMR(27) message MNSMS-ERROR-IND received in state WAIT_FOR_RP_ACK
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:343 SMR(27) TX SMS MNSMS-ERROR-IND
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:143 SMR(27) new RP state WAIT_FOR_RP_ACK -> IDLE
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:189 SMR(27) TX: MNSMS-REL-REQ
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:472 SMC(27) message MNSMS-REL-REQ received in state IDLE
20170717221252317 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:168 Got MMSMS_REL_REQ, destroying transaction.
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smr.c:96 SMR(27) clearing SMR instance
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:100 SMC(27) clearing instance
20170717221252317 DLSMS <0027> ../../../src/gsm/gsm0411_smc.c:107 SMC(27) dropping pending message
20170717221252317 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:1039 Transaction contains SMS.
20170717221252328 DLSMS <0027> ../../../src/libmsc/sms_queue.c:156 Sending SMS 27 failed 0 times.
20170717221252328 DREF <000e> ../../../src/libmsc/sms_queue.c:129 VLR subscr MSISDN:701 usage decreases to: 5
20170717221252328 DLSMS <0027> ../../../src/libmsc/sms_queue.c:367 Triggering SMS queue
20170717221252328 DREF <000e> ../../../src/libmsc/gsm_04_11.c:79 VLR subscr MSISDN:701 usage decreases to: 4
20170717221252328 DREF <000e> ../../../src/libmsc/transaction.c:127 VLR subscr MSISDN:701 usage decreases to: 3
20170717221252328 DREF <000e> ../../../src/libmsc/transaction.c:134 MSISDN:701: MSC conn use - 1 == 2
20170717221252328 DMM <0002> ../../../src/libmsc/osmo_msc.c:58 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
20170717221252328 DMM <0002> ../../../src/libmsc/subscr_conn.c:168 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
20170717221252329 DMM <0002> ../../../src/libmsc/subscr_conn.c:169 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
20170717221252329 DMM <0002> ../../../src/libmsc/subscr_conn.c:255 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
20170717221252329 DVLR <001e> ../../../src/libmsc/subscr_conn.c:255 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
20170717221252329 DVLR <001e> ../../../src/libmsc/subscr_conn.c:255 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000014701)[0x739180]
20170717221252329 DVLR <001e> ../../../src/libmsc/subscr_conn.c:255 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_DONE}: Freeing instance
20170717221252329 DVLR <001e> ../../src/fsm.c:273 Process_Access_Request_VLR(901700000014701)[0x7392b0]{PR_ARQ_S_DONE}: Deallocated
20170717221252329 DREF <000e> ../../../src/libmsc/subscr_conn.c:241 MSISDN:701: MSC conn use - 1 == 1
20170717221252329 DMM <0002> ../../../src/libmsc/subscr_conn.c:255 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_RELEASED}: Freeing instance
20170717221252329 DMM <0002> ../../src/fsm.c:273 Subscr_Conn(901700000014701)[0x739180]{SUBSCR_CONN_S_RELEASED}: Deallocated
20170717221252329 DREF <000e> ../../../src/libmsc/osmo_msc.c:106 MSISDN:701: MSC conn use - 1 == 0
20170717221252329 DRLL <0000> ../../../src/libmsc/osmo_msc.c:212 subscr MSISDN:701: Freeing subscriber connection
20170717221252329 DREF <000e> ../../../src/libmsc/osmo_msc.c:214 VLR subscr MSISDN:701 usage decreases to: 2
20170717221252329 DLINP <0023> ../../src/stream.c:253 connected write
20170717221252329 DLINP <0023> ../../src/stream.c:178 sending data
20170717221252329 DLINP <0023> ../../src/stream.c:253 connected write
20170717221252329 DLINP <0023> ../../src/stream.c:178 sending data
20170717221253329 DLSMS <0027> ../../../src/libmsc/sms_queue.c:252 Attempting to send 20 SMS
20170717221253332 DREF <000e> ../../../src/libmsc/db.c:604 VLR subscr MSISDN:701 usage increases to: 3
20170717221253332 DLSMS <0027> ../../../src/libmsc/sms_queue.c:268 Sending SMS round 1
20170717221253332 DREF <000e> ../../../src/libmsc/sms_queue.c:122 VLR subscr MSISDN:701 usage increases to: 4
20170717221253332 DLSMS <0027> ../../../src/libmsc/gsm_04_11.c:1018 Sending SMS: no connection open, start paging MSISDN:701
20170717221253332 DMM <0002> ../../../src/libmsc/gsm_subscriber.c:147 Subscriber MSISDN:701 not paged yet, start paging.
Updated by neels almost 7 years ago
To clarify, 0x332 is the inst->id, the msg_type is 1
LOGP(DLSMS, LOGL_NOTICE,
SMC_LOG_STR "message 0x%x/%u unhandled at this "
"state %s.\n", inst->id, msg_type, cp_msg_type,
smc_state_names[inst->cp_state]);
It seems we expect a GSM411_MT_CP_ACK == 0x04, but receive 0x01 being GSM411_MT_CP_DATA. Is that a bug in the Nokia 1100??
Updated by neels almost 7 years ago
neels wrote:
To clarify, 0x332 is the inst->id, the msg_type is 1
[...]
Wrong, the SMC_LOG_STR contains another format item, so 0x332 is the msg_type, 1 is the cp_msg_type.
msg_type is 0x332 = GSM411_MMSMS_DATA_IND passed in as literal constant from gsm0411_rcv_sms().
cp_msg_type is 1, passed in from the same function and there confusingly still called msg_type.
Otherwise this conclusion still seems valid:
It seems we expect a GSM411_MT_CP_ACK == 0x04, but receive 0x01 being GSM411_MT_CP_DATA. Is that a bug in the Nokia 1100??
Updated by neels almost 7 years ago
According to wireshark, there is a CP-DATA with an RPDU, which contains an RP-ACK (discriminator 0x02, RP-Message reference 0x00).
Updated by laforge almost 7 years ago
- Priority changed from Normal to Low
I think it's a bug in the phone.
We need to receive ACKs on both the CP (lower) and RP (higher) layer. Now the phone is sending us an ACK on the higher RP layer before the lower CP layer sends an ack. This is an impossibility. If the message was not processed (and ACKed) by the lower layer, how can it arrive and be ACKed on the higher layer?
Updated by roox about 6 years ago
I also just ran into that issue while running master branches of the new osmocom stack.
Phones that are affected:
Model: Nokia 6300 IC: 661U-RM217 Type: RM-217 Firmware: V07.21 (05-11-08)
Model: Nokia 6230 IC: 661AD-RH12 Type: RH-12 Firmware: V5.24 (25-11-04)
The common thing between these phones is that they are all based on Nokia's DCT4 architecture.
https://en.wikipedia.org/wiki/List_of_Nokia_products
Updated by neels about 6 years ago
A sensible thing to do seems to detect and ignore this situation, possibly make it optional by vty config. Not sure when we'll find time to address this, patches welcome!
Updated by fixeria over 5 years ago
I think it's a bug in the phone.
Would like to inform that I also experienced this problem with Nokia 3310.
Actions
