error_unknown (Reason for termination: badarg)

[tisba]

From time to time we see error_unknown in tsung.log. In the node logs we see errors like this:

=ERROR REPORT==== 1-Aug-2018::14:49:06 ===
** State machine <0.3472.0> terminating 
** Last message in was {timeout,#Ref<0.2210292323.660602881.256781>,
                                end_thinktime}
** When State == think
**      Data  == {state_rcv,none,
                     {{0,0,0,0},0},
                     undefined,0,10000,"target.example.com",443,ts_ssl,
                     {proto_opts,negotiate,negotiate,"/http-bind/",false,
                         false,false,"/chat","binary",[],10,3,600000,infinity,
                         infinity,32768,32768,32768,32768,[],true,true},
                     false,2,undefined,true,undefined,-576459248070357934,7,7,
                     false,undefined,0,[],<<>>,
                     {http,0,0,-1,
                         {none,none},
                         false,false,
                         {false,false},
                         [],"User-Agent Foo",[]},
                     0,3014,524288,524288,
                     [{tsung_userid,3014}],
                     ts_http,[],undefined,protocol_local}
** Reason for termination = 
** badarg

The error happens every so often, but I currently have not a good clue how to reproduce it or were to start digging :-/

[tisba]

ping @nniclausse. Can you maybe help so that I can locate or even fix the problem?

[visualcshape]

Hello, I have same problem here, this error seems randomly occurred, but more load I gave, this error appear more frequently.

The tsung are running on the AWS EC2 instances. I've configured two t3.small instances as node and one t3.medium as a controller. These tsung nodes are running under Amazon Linux 2. Erlang version is OTP21, and OpenSSL 1.0.2k-fips. Our XMPP servers are running Ejabberd 18.09.19, OTP 21, and OpenSSL 1.1.0f.

Here is my log file from one of tsung cluster.
Some sensitive info was replaced by HOST, DOMAIN, USERNAME, and PASSWORD respectively
where sesame in the log does not appeared in my config file

=INFO REPORT==== 14-Nov-2018::08:31:35 ===
           ts_client:(6:<0.134.0>) (Re)connect from 0.0.0.0:0 to HOST:5222, Error: {tls_alert,
                                                                                                  "bad record mac"}

=INFO REPORT==== 14-Nov-2018::08:31:35 ===
           ts_client:(5:<0.134.0>) Stop in state think, reason= {badarg,
                                                                 [{erlang,
                                                                   atom_to_list,
                                                                   [{tls_alert,
                                                                     "bad record mac"}],
                                                                   []},
                                                                  {ts_client,
                                                                   reconnect,
                                                                   5,
                                                                   [{file,
                                                                     "src/tsung/ts_client.erl"},
                                                                    {line,
                                                                     1044}]},
                                                                  {ts_client,
                                                                   handle_next_request,
                                                                   2,
                                                                   [{file,
                                                                     "src/tsung/ts_client.erl"},
                                                                    {line,
                                                                     821}]},
                                                                  {gen_fsm,
                                                                   handle_msg,
                                                                   8,
                                                                   [{file,
                                                                     "gen_fsm.erl"},
                                                                    {line,
                                                                     486}]},
                                                                  {proc_lib,
                                                                   wake_up,3,
                                                                   [{file,
                                                                     "proc_lib.erl"},
                                                                    {line,
                                                                     259}]}]}

=ERROR REPORT==== 14-Nov-2018::08:31:35 ===
** State machine <0.134.0> terminating 
** Last message in was {timeout,#Ref<0.3161090635.417333249.111772>,
                                end_thinktime}
** When State == think
**      Data  == {state_rcv,none,
                     {{0,0,0,0},0},
                     undefined,0,10000,"HOST",5222,ts_ssl,
                     {proto_opts,negotiate,negotiate,"/http-bind/",false,
                         false,false,"/chat","binary",[],10,3,600000,infinity,
                         infinity,32768,32768,32768,32768,[],true,false},
                     true,1,
                     {ts_request,no_ack,false,[],[],
                         {jabber,random,0,[],raw,false,undefined,undefined,
                             undefined,0,
                             {domain,"DOMAIN"},
                             undefined,"USERNAME","sesame",undefined,
                             undefined,"chat","Available",
                             {undef_var,muc_service},
                             undefined,undefined,
                             {undef_var,pubsub_service},
                             "Tsung Group",undefined,"tsung",undefined,
                             undefined,"1.0",undefined,undefined,undefined,
                             undefined,"USERNAME",undefined,undefined,
                             undefined},
                         true,undefined,undefined,undefined},
                     true,-576460633679394888,-576460749795730785,4,26,true,
                     -576460633679394888,0,[],<<>>,
                     {jabber_session,user_defined,undefined,default,
                         "USERNAME","PASSWORD","DOMAIN"},
                     0,6,524288,524288,
                     [{counter,6},
                      {resource_id,"RESOURCE"},
                      {password,<<"PASSWORD">>},
                      {username,<<"USERNAME">>},
                      {tsung_userid,6}],
                     ts_jabber,[],undefined,full}
** Reason for termination = 
** {badarg,[{erlang,atom_to_list,[{tls_alert,"bad record mac"}],[]},
            {ts_client,reconnect,5,
                       [{file,"src/tsung/ts_client.erl"},{line,1044}]},
            {ts_client,handle_next_request,2,
                       [{file,"src/tsung/ts_client.erl"},{line,821}]},
            {gen_fsm,handle_msg,8,[{file,"gen_fsm.erl"},{line,486}]},
            {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,259}]}]}

and here is my config file
I have tried to add/remove <option name="ssl_reuse_sessions" value="false"/> and <option name="ssl_versions" value="'tlsv1.2'"/> but with no luck.

<?xml version="1.0"?>
<!DOCTYPE tsung SYSTEM "/usr/local/share/tsung/tsung-1.0.dtd" [] >
<tsung loglevel="info" dumptraffic="true" version="1.0">
    <clients>
        <client host="localhost" maxusers="50000"/>
        <client host="ip-***" maxusers="50000"/>
    </clients>
    
    <servers>
        <server host="HOST" port="5222" type="tcp" />
    </servers>

    <load>
        <arrivalphase duration="60" phase="1" unit="second">
            <users unit="second" arrivalrate="10" maxnumber="800"/>
            <session_setup name="camera_online" probability="100"/>
        </arrivalphase>
        <arrivalphase duration="60" phase="2" unit="second">
            <users unit="second" arrivalrate="10" maxnumber="400"/>
            <session_setup name="extra_camera_online" probability="100"/>
        </arrivalphase>
    </load>

    <options>
        <option name="ssl_reuse_sessions" value="false"/>
        <option name="ssl_versions" value="'tlsv1.2'"/>
        <option type="ts_jabber" name="global_number" value="100"/>
        <option type="ts_jabber" name="domain" value="DOMAIN"/>
        <option type="ts_jabber" name="username" value="USERNAME"/>
        <option type="ts_jabber" name="userid_max" value="0"/>
        <option type="ts_jabber" name="fileid_delimiter" value=","/>
        <option name="file_server" id="basic_users" value="/***/tsung-config/tsung-xmpp-basic-users.csv"/>
        <option name="file_server" id="random_pool_users" value="/***/tsung-config/tsung-xmpp-random-pool-users.csv"/>
        <option type="ts_jabber" name="random_from_fileid" value="random_pool_users"/>
        <option type="ts_jabber" name="offline_from_fileid" value="basic_users"/>
    </options>

    <sessions>
        <!-- basic camera online -->
        <session name="camera_online" type="ts_jabber" probability="0" bidi="true">
            <setdynvars sourcetype="file" fileid="basic_users" delimiter="," order="iter">
                <var name="username"/>
                <var name="password"/>
            </setdynvars>


            <setdynvars sourcetype="value" value="camera_1">
                <var name="resource_id"/>
            </setdynvars>

            <request subst="true">
                <jabber ack="no_ack" type="connect">
                    <xmpp_authenticate passwd="%%_password%%" username="%%_username%%"/>
                </jabber>
            </request>

            <transaction name="starttls">
                <request>
                    <jabber ack="bidi_ack" type="starttls"/>
                </request>
                <request>
                    <jabber ack="local" type="connect"/>
                </request>
            </transaction>

            <thinktime value="3"/>

            <transaction name="authenticate">
                <request subst="true">
                    <jabber ack="local" type="auth_sasl" resource="%%_resource_id%%"/>
                </request>
                <request subst="true">
                    <jabber ack="local" type="connect" resource="%%_resource_id%%"/>
                </request>
                <request subst="true">
                    <jabber ack="local" type="auth_sasl_bind" resource="%%_resource_id%%"/>
                </request>
                <request subst="true">
                    <jabber ack="local" type="auth_sasl_session" resource="%%_resource_id%%"/>
                </request>
            </transaction>

            <transaction name="initial_presence">
                <request subst="true">
                    <jabber ack="no_ack" type="presence:initial" resource="%%_resource_id%%"/>
                </request>
            </transaction>

            <for from="1" to="25" var="counter">
                <transaction name="camera_1_ping">
                    <request>
                        <jabber ack="no_ack" type="raw" data=""/>
                    </request>
                </transaction>
                <thinktime random="true" max="25" min="20"/>
            </for>

            <transaction name="close">
                <request subst="true">
                    <jabber ack="no_ack" type="close" resource="%%_resource_id%%"/>
                </request>
            </transaction>
        </session>

        <!-- extra camera online -->
        <session name="extra_camera_online" type="ts_jabber" probability="0" bidi="true">
            <setdynvars sourcetype="file" fileid="basic_users" delimiter="," order="iter">
                <var name="username"/>
                <var name="password"/>
                <var name="user_id" />
            </setdynvars>

            <setdynvars sourcetype="value" value="camera_2">
                <var name="resource_id"/>
            </setdynvars>

            <request subst="true">
                <jabber ack="no_ack" type="connect">
                    <xmpp_authenticate passwd="%%_password%%" username="%%_username%%"/>
                </jabber>
            </request>

            <transaction name="starttls">
                <request>
                    <jabber ack="bidi_ack" type="starttls"/>
                </request>
                <request>
                    <jabber ack="local" type="connect"/>
                </request>
            </transaction>

            <thinktime value="3"/>

            <transaction name="authenticate">
                <request subst="true">
                    <jabber ack="local" type="auth_sasl" resource="%%_resource_id%%"/>
                </request>
                <request subst="true">
                    <jabber ack="local" type="connect" resource="%%_resource_id%%"/>
                </request>
                <request subst="true">
                    <jabber ack="local" type="auth_sasl_bind" resource="%%_resource_id%%"/>
                </request>
                <request subst="true">
                    <jabber ack="local" type="auth_sasl_session" resource="%%_resource_id%%"/>
                </request>
            </transaction>

            <transaction name="initial_presence">
                <request subst="true">
                    <jabber ack="no_ack" type="presence:initial" resource="%%_resource_id%%"/>
                </request>
            </transaction>

            <for from="1" to="25" var="counter">
                <transaction name="camera_2_ping">
                    <request>
                        <jabber ack="no_ack" type="raw" data=""/>
                    </request>
                </transaction>
                <thinktime random="true" max="25" min="20"/>
            </for>

            <transaction name="close">
                <request subst="true">
                    <jabber ack="no_ack" type="close" resource="%%_resource_id%%"/>
                </request>
            </transaction>
        </session>
    </sessions>
    
</tsung>

Please help, thank you.

[tisba]

@victorqhong you actually have a pretty "good" error message. bad record mac indicates that there is a problem with the TLS handshake. I'm struggling with (other) TLS handshake issues as well for some time now using Erlang :(

Have you tried to update OpenSSL to 1.1.1a or even the latest 1.1.1b? Depending on how your target host is configured, this might help. If you can give this a try without TLS it should work (AFAIK).

Actually, the launched Tsung Client is dying while trying to translate the error message. #343 contains a fix for the error reporting, but won't resolve the underlying issue you are seeing.

[jalawala]

Hi All,
is there any progress on this issue? I am also facing the similar issue.

ts_client:(5:<0.949.0>) Stop in state think, reason= {badarg,
[{erlang,
atom_to_list,
[{tls_alert,
{unexpected_message,
"received CLIENT ALERT: Fatal - Unexpected Message"}}],
[]},
{ts_client,
reconnect,
5,
[{file,

Tsung.log

Connections drops from 297 to 0
Line 1304: stats: connected 0 297
Line 3026: stats: connected 0 2

I also posted an issue #358, Pls help

[tisba]

@testcoderepo123 that's a different error. The TLS alert indicates that there is an issue with the TLS connection with your target.

[jalawala]

What could be the reason for this issue? Attached is my config. Can you pls check if I am missing out anything? I am really blocked on this....Could you pls help?
I see tsung client connects to XMPP but after few mins, I see all connection dropped bcz of below error

ts_client:(5:<0.195.0>) Stop in state think, reason= {badarg,
[{erlang,
atom_to_list,
[{tls_alert,
{unexpected_message,
"received CLIENT ALERT: Fatal - Unexpected Message"}}],
[]},
{ts_client,
reconnect,
5,
[{file,
"src/tsung/ts_client.erl"},
{line,
1044}]},
{ts_client,

tsung_config_file_new.txt