[OpenSIPS-Users] misterious error on receive smpp message causing a rebind while the session is up.
johan
johan at democon.be
Tue Sep 3 06:19:37 EDT 2019
Hello,
using opensips3.0.
Opensips is on ip 10.3.0.150, smpp relay is on 80.84.24.81.
They are connected with a trx link.
33662124034 is a mobile number
33757936414 is a user on opensips, this user is connected on TLS.
Upon receiving a message from the smpp relay I find below in the logs.
Sep 3 09:22:48 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:handle_submit_or_deliver_cmd: Received SMPP
message#012FROM:#01101 01 33662124034#012TO:#01101 01
33757936414#012LEN:#01110#012Test11resp
Sep 3 09:22:48 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:tcp_conn_get: con found in state 0
Sep 3 09:22:48 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:tcp_conn_get: tcp connection found (0x7fbe9a97bb50) already in
this process ( 15 ) , fd = 5
Sep 3 09:22:48 hendrix /data/opensips/sbin/opensips[3111]:
ERROR:core:tsend_stream: tsend_stream: failed to send: (14) Bad address
Sep 3 09:22:48 hendrix /data/opensips/sbin/opensips[3111]:
ERROR:proto_smpp:smpp_send_msg: failed to send data!
Net result of this eror is that opensips thinks that the smpp link is
down and hence sends a new bindtransceiver request 3 seconds later. The
smpp relay rejects this with reason "ESME already in bound state".
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:wait_handler: done
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
INFO:proto_smpp:send_bind: binding session with system_id "BELDUSTMO"
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
DBG:core:probe_max_sock_buff: getsockopt: snd is initially 16384
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
INFO:core:probe_max_sock_buff: using snd buffer of 416 kb
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 130
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3100]:
DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
DBG:core:print_ip: tcpconn_new: new tcp connection to: 80.84.24.81
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
DBG:core:tcpconn_new: on port 2775, proto 10
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
INFO:proto_smpp:smpp_conn_init: smpp_conn_init called
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
DBG:proto_smpp:send_bind: sent 43 bytes on smpp connection 0x7fbe9a946268
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
DBG:proto_smpp:bind_session: succsessfully bound BICS
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3103]:
ERROR:proto_smpp:smpp_send_msg: cannot fetch connection for BICS (0)
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:handle_worker: read response= 7fbe9a946268, 2, fd 302 from 7 (3103)
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:tcpconn_add: hashes: 647, 160
Sep 3 09:22:51 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:io_watch_add: [TCP_main] io_watch_add op (302 on 5)
(0x5575c03fc700, 302, 19, 0x7fbe9a946268,1), fd_no=34/1024
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:handle_tcpconn_ev: data available on 0x7fbe9a946268 302
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 3 302
(0x5575c03fc700, 302, 3, 0x0,0x1) fd_no=35 called
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:send2worker: to tcp worker 1 (0), 0x7fbe9a946268 rw 1
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:handle_io: We have received conn 0x7fbe9a946268 with rw 1 on fd 5
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:io_watch_add: [TCP_worker] io_watch_add op (5 on 88)
(0x5575c03fc700, 5, 19, 0x7fbe9a946268,1), fd_no=4/1024
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:smpp_read_req: Using the global ( per process ) buff
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:smpp_parse_headers: received a complete message
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:smpp_handle_req: completely received a message
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:smpp_handle_req: Nothing more to read on TCP conn
0x7fbe9a946268, currently in state 0
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:handle_smpp_msg: Received SMPP command 80000009
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:handle_bind_transceiver_resp_cmd: Received
bind_transceiver_resp command
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
ERROR:proto_smpp:handle_bind_transceiver_resp_cmd: Error in
bind_transceiver_resp 00000005
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:smpp_read_req: tcp_read_req end
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:smpp_read_req: Using the global ( per process ) buff
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:proto_tcp_read: EOF on 0x7fbe9a946268, FD 5
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:proto_smpp:smpp_read_req: EOF received
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:io_watch_del: [TCP_worker] io_watch_del op on index 0 5
(0x5575c03fc700, 5, 0, 0x10,0x3) fd_no=5 called
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:tcpconn_release: releasing con 0x7fbe9a946268, state -1,
fd=-1, id=1553651872
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3111]:
DBG:core:tcpconn_release: extra_data (nil)
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:handle_tcp_worker: response= 7fbe9a946268, -1 from tcp worker 0 (1)
Sep 3 09:22:53 hendrix /data/opensips/sbin/opensips[3119]:
DBG:core:tcpconn_destroy: delaying (0x7fbe9a946268, flags 0018) ref = 1 ...
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:timer_routine: timer routine:2,tl=0x7fbe9a993fc0
next=0x7fbe9a992550, timeout=491883
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:wait_handler: removing 0x7fbe9a993f40 from table
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:delete_cell: delete transaction 0x7fbe9a993f40
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:wait_handler: done
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:timer_routine: timer routine:2,tl=0x7fbe9a992550 next=(nil),
timeout=491883
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:wait_handler: removing 0x7fbe9a9924d0 from table
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:delete_cell: delete transaction 0x7fbe9a9924d0
Sep 3 09:22:54 hendrix /data/opensips/sbin/opensips[3101]:
DBG:tm:wait_handler: done
Attached also a wireshark text trace which show that the ESME is indeed
bound and that bind_transceiver is sent after Deliver_sm.
Can somebody please explain what that error means and what I need to do
to troubleshoot this ?
If needed I can provide a full opensips.log of these few seconds (>1200
lijnen)
Best regards, Johan.
-------------- next part --------------
No. Time Source Destination Protocol Length Info
1 2019-09-03 11:22:45,448724 10.3.0.150 80.84.24.81 SMPP 80 SMPP Enquire_link
Frame 1: 80 bytes on wire (640 bits), 80 bytes captured (640 bits)
Enc IPv4, SPI 0xc5afa548
Internet Protocol Version 4, Src: 10.3.0.150, Dst: 80.84.24.81
Transmission Control Protocol, Src Port: 52731, Dst Port: 2775, Seq: 1, Ack: 1, Len: 16
Short Message Peer to Peer, Command: Enquire_link, Seq: 98555, Len: 16
Length: 16
Operation: Enquire_link (0x00000015)
Sequence #: 98555
No. Time Source Destination Protocol Length Info
2 2019-09-03 11:22:45,463210 80.84.24.81 10.3.0.150 SMPP 80 SMPP Enquire_link - resp: "Ok"
Frame 2: 80 bytes on wire (640 bits), 80 bytes captured (640 bits)
Enc IPv4, SPI 0xcf4a3183
Internet Protocol Version 4, Src: 80.84.24.81, Dst: 10.3.0.150
Transmission Control Protocol, Src Port: 2775, Dst Port: 52731, Seq: 1, Ack: 17, Len: 16
Short Message Peer to Peer, Command: Enquire_link - resp, Status: "Ok", Seq: 98555, Len: 16
Length: 16
Operation: Enquire_link - resp (0x80000015)
Result: Ok (0x00000000)
Sequence #: 98555
No. Time Source Destination Protocol Length Info
3 2019-09-03 11:22:45,762208 10.3.0.150 80.84.24.81 SMPP 125 SMPP Submit_sm
Frame 3: 125 bytes on wire (1000 bits), 125 bytes captured (1000 bits)
Enc IPv4, SPI 0xc5afa548
Internet Protocol Version 4, Src: 10.3.0.150, Dst: 80.84.24.81
Transmission Control Protocol, Src Port: 52731, Dst Port: 2775, Seq: 17, Ack: 17, Len: 61
Short Message Peer to Peer, Command: Submit_sm, Seq: 98556, Len: 61
Length: 61
Operation: Submit_sm (0x00000004)
Sequence #: 98556
Service type: (Default)
Type of number (originator): International (0x01)
Numbering plan indicator (originator): ISDN (E163/E164) (0x01)
Originator address: 33757936414
Type of number (recipient): International (0x01)
Numbering plan indicator (recipient): ISDN (E163/E164) (0x01)
Recipient address: 33662124034
.... ..00 = Messaging mode: Default SMSC mode (0x0)
..00 00.. = Message type: Default message type (0x0)
00.. .... = GSM features: No specific features selected (0x0)
Protocol id.: 0x00
Priority level: GSM: None ANSI-136: Bulk IS-95: Normal (0x00)
Scheduled delivery time: Immediate delivery
Validity period: SMSC default validity period
.... ..00 = Delivery receipt: No SMSC delivery receipt requested (0x0)
.... 00.. = Message type: No recipient SME acknowledgement requested (0x0)
...0 .... = Intermediate notif: No intermediate notification requested (0x0)
.... ...0 = Replace: Don't replace (0x0)
Data coding: 0x00
Predefined message: 0
Message length: 6
Message: 546573743132
No. Time Source Destination Protocol Length Info
4 2019-09-03 11:22:46,164966 80.84.24.81 10.3.0.150 SMPP 89 SMPP Submit_sm - resp: "Ok"
Frame 4: 89 bytes on wire (712 bits), 89 bytes captured (712 bits)
Enc IPv4, SPI 0xcf4a3183
Internet Protocol Version 4, Src: 80.84.24.81, Dst: 10.3.0.150
Transmission Control Protocol, Src Port: 2775, Dst Port: 52731, Seq: 17, Ack: 78, Len: 25
Short Message Peer to Peer, Command: Submit_sm - resp, Status: "Ok", Seq: 98556, Len: 25
Length: 25
Operation: Submit_sm - resp (0x80000004)
Result: Ok (0x00000000)
Sequence #: 98556
Message id.: 208F89EB
No. Time Source Destination Protocol Length Info
5 2019-09-03 11:22:48,175465 80.84.24.81 10.3.0.150 SMPP 129 SMPP Deliver_sm
Frame 5: 129 bytes on wire (1032 bits), 129 bytes captured (1032 bits)
Enc IPv4, SPI 0xcf4a3183
Internet Protocol Version 4, Src: 80.84.24.81, Dst: 10.3.0.150
Transmission Control Protocol, Src Port: 2775, Dst Port: 52731, Seq: 42, Ack: 78, Len: 65
Short Message Peer to Peer, Command: Deliver_sm, Seq: 1, Len: 65
Length: 65
Operation: Deliver_sm (0x00000005)
Sequence #: 1
Service type: (Default)
Type of number (originator): International (0x01)
Numbering plan indicator (originator): ISDN (E163/E164) (0x01)
Originator address: 33662124034
Type of number (recipient): International (0x01)
Numbering plan indicator (recipient): ISDN (E163/E164) (0x01)
Recipient address: 33757936414
.... ..00 = Messaging mode: Default SMSC mode (0x0)
..00 00.. = Message type: Default message type (0x0)
00.. .... = GSM features: No specific features selected (0x0)
Protocol id.: 0x00
Priority level: GSM: None ANSI-136: Bulk IS-95: Normal (0x00)
Scheduled delivery time: Immediate delivery
Validity period: SMSC default validity period
.... ..01 = Delivery receipt: Delivery receipt requested (for success or failure) (0x1)
.... 00.. = Message type: No recipient SME acknowledgement requested (0x0)
...0 .... = Intermediate notif: No intermediate notification requested (0x0)
.... ...0 = Replace: Don't replace (0x0)
Data coding: 0x00
Predefined message: 0
Message length: 10
Message: 54657374313172657370
No. Time Source Destination Protocol Length Info
6 2019-09-03 11:22:51,387212 10.3.0.150 80.84.24.81 SMPP 107 SMPP Bind_transceiver
Frame 6: 107 bytes on wire (856 bits), 107 bytes captured (856 bits)
Enc IPv4, SPI 0xc5afa548
Internet Protocol Version 4, Src: 10.3.0.150, Dst: 80.84.24.81
Transmission Control Protocol, Src Port: 51549, Dst Port: 2775, Seq: 1, Ack: 1, Len: 43
Short Message Peer to Peer, Command: Bind_transceiver, Seq: 98558, Len: 43
Length: 43
Operation: Bind_transceiver (0x00000009)
Sequence #: 98558
System ID: BELDUSTMO
Password: mypassword
System type: OTT
Version (if): 3.4
Type of number: International (0x01)
Numbering plan indicator: ISDN (E163/E164) (0x01)
No. Time Source Destination Protocol Length Info
7 2019-09-03 11:22:53,406210 80.84.24.81 10.3.0.150 SMPP 80 SMPP Bind_transceiver - resp: "ESME already in bound state"
Frame 7: 80 bytes on wire (640 bits), 80 bytes captured (640 bits)
Enc IPv4, SPI 0xcf4a3183
Internet Protocol Version 4, Src: 80.84.24.81, Dst: 10.3.0.150
Transmission Control Protocol, Src Port: 2775, Dst Port: 51549, Seq: 1, Ack: 44, Len: 16
Short Message Peer to Peer, Command: Bind_transceiver - resp, Status: "ESME already in bound state", Seq: 98558, Len: 16
Length: 16
Operation: Bind_transceiver - resp (0x80000009)
Result: ESME already in bound state (0x00000005)
Sequence #: 98558
More information about the Users
mailing list